Detected new errors in tracker demo logs

[josecelano]

Relates to: https://github.com/torrust/torrust-tracker/issues/1447

Invalid announce event

tracker  | 2025-04-14T07:05:20.191679Z ERROR process_request:handle_packet{server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id="de85fd34-65dd-40b5-b622-f62577671b81"}:handle_error{req_kind=None client_socket_addr=*.*.*.*:6886 server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id=de85fd34-65dd-40b5-b622-f62577671b81 cookie_valid_range=1744614199.1916456..1744614321.1916456 e=RequestParseError { request_parse_error: Sendable { connection_id: ConnectionId(I64(-2584382343165663689)), transaction_id: TransactionId(I32(976017587)), err: "Invalid announce event" } }}: UDP TRACKER: response error error=error when phrasing request: Sendable { connection_id: ConnectionId(I64(-2584382343165663689)), transaction_id: TransactionId(I32(976017587)), err: "Invalid announce event" } client_socket_addr=*.*.*.*:6886 server_socket_addr=0.0.0.0:6969 request_id=de85fd34-65dd-40b5-b622-f62577671b81

The errors are produced while trying to parse the raw request with an aquatic UDP crate.

The event must be 0..=3. See https://github.com/greatest-ape/aquatic/blob/34b45e923f84421181fc43cf5e20709e69ce0dfd/crates/udp_protocol/src/request.rs#L201-L215.

Invalid action

tracker  | 2025-04-14T08:04:08.166353Z ERROR process_request:handle_packet{server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id="160808b9-7b55-44d4-9935-cc3ec8354517"}:handle_error{req_kind=None client_socket_addr=*.*.*.*:1259 server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id=160808b9-7b55-44d4-9935-cc3ec8354517 cookie_valid_range=1744617727.1662765..1744617849.1662765 e=RequestParseError { request_parse_error: Unsendable { err: Right("Invalid action") } }}: UDP TRACKER: response error error=error when phrasing request: Unsendable { err: Right("Invalid action") } client_socket_addr=*.*.*.*:1259 server_socket_addr=0.0.0.0:6969 request_id=160808b9-7b55-44d4-9935-cc3ec8354517

Port can't be 0

tracker  | 2025-04-14T08:07:43.167648Z ERROR process_request:handle_packet{server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id="f47d2172-c6af-4319-aa5e-52d217fc113a"}:handle_error{req_kind=None client_socket_addr=*.*.*.*:22598 server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id=f47d2172-c6af-4319-aa5e-52d217fc113a cookie_valid_range=1744617942.1676147..1744618064.1676147 e=RequestParseError { request_parse_error: Sendable { connection_id: ConnectionId(I64(9072480440622786977)), transaction_id: TransactionId(I32(-1601379324)), err: "Port can't be 0" } }}: UDP TRACKER: response error error=error when phrasing request: Sendable { connection_id: ConnectionId(I64(9072480440622786977)), transaction_id: TransactionId(I32(-1601379324)), err: "Port can't be 0" } client_socket_addr=*.*.*.*:22598 server_socket_addr=0.0.0.0:6969 request_id=f47d2172-c6af-4319-aa5e-52d217fc113a

Protocol identifier missing

tracker  | 2025-04-14T08:11:11.345973Z ERROR process_request:handle_packet{server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id="8d75cf90-a8c1-4093-85da-a78c770b2ca4"}:handle_error{req_kind=None client_socket_addr=*.*.*.*:46602 server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id=8d75cf90-a8c1-4093-85da-a78c770b2ca4 cookie_valid_range=1744618150.3459253..1744618272.3459253 e=RequestParseError { request_parse_error: Unsendable { err: Right("Protocol identifier missing") } }}: UDP TRACKER: response error error=error when phrasing request: Unsendable { err: Right("Protocol identifier missing") } client_socket_addr=*.*.*.*:46602 server_socket_addr=0.0.0.0:6969 request_id=8d75cf90-a8c1-4093-85da-a78c770b2ca4

Couldn't parse action

tracker  | 2025-04-14T13:21:29.343255Z ERROR process_request:handle_packet{server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id="26769e63-c65c-4a03-94b9-47496a412a3e"}:handle_error{req_kind=None client_socket_addr=*.*.*.*:62410 server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id=26769e63-c65c-4a03-94b9-47496a412a3e cookie_valid_range=1744636768.3432279..1744636890.3432279 e=RequestParseError { request_parse_error: Unsendable { err: Right("Couldn't parse action") } }}: UDP TRACKER: response error error=error when phrasing request: Unsendable { err: Right("Couldn't parse action") } client_socket_addr=*.*.*.*:62410 server_socket_addr=0.0.0.0:6969 request_id=26769e63-c65c-4a03-94b9-47496a412a3e

We can also change the logging threshold for these errors to WARNING because there are many of them, and they are not application errors.

[josecelano]

I'm running this command:

docker compose logs -f tracker | grep -v -F -e "Invalid announce event" -e 'Connection cookie error' -e INFO -e "Invalid action" -e "Udp::run_udp_server::loop aborting request" -e "Port can't be 0" -e "Protocol identifier missing" -e "Couldn't parse action"

To filter out common client errors when reviewing the logs.