torrust-tracker icon indicating copy to clipboard operation
torrust-tracker copied to clipboard

Change the logging threshold for connection ID error to `WARNING`

Open josecelano opened this issue 7 months ago • 0 comments

Relates to:

  • https://github.com/torrust/torrust-tracker/issues/1136
  • https://github.com/torrust/torrust-demo/issues/14
  • https://github.com/torrust/torrust-tracker/issues/1448

In the Torrust Tracker demo, we have had many errors related to the connection ID.

Those errors produce these entries in the logs:

cookie value is expired

tracker  | 2025-04-14T07:05:20.218017Z ERROR process_request:handle_packet{server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id="cc6e0a00-53c6-4411-b9d5-94abaa4ca601"}:handle_error{req_kind=Some(Announce) client_socket_addr=*.*.*.*:10955 server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id=cc6e0a00-53c6-4411-b9d5-94abaa4ca601 cookie_valid_range=1744614199.2179515..1744614321.2179515 e=UdpAnnounceError { source: ConnectionCookieError { source: ValueExpired { expired_value: 1744529479.3915782, min_value: 1744614199.2179515 } } }}: UDP TRACKER: response error error=tracker announce error: Connection cookie error: cookie value is expired: 1744529479.3915782, expected > 1744614199.2179515 client_socket_addr=*.*.*.*:10955 server_socket_addr=0.0.0.0:6969 request_id=cc6e0a00-53c6-4411-b9d5-94abaa4ca601 transaction_id=816049563
05Z ERROR process_request:handle_packet{server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id="82473f7d-69ab-4377-bb13-8c4dbda3fd74"}:handle_error{req_kind=Some(Announce) client_socket_addr=*.*.*.*:50075 server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id=82473f7d-69ab-4377-bb13-8c4dbda3fd74 cookie_valid_range=1744614199.079339..1744614321.079339 e=UdpAnnounceError { source: ConnectionCookieError { source: ValueExpired { expired_value: -1.0019048947253183e-302, min_value: 1744614199.079339 } } }}: UDP TRACKER: response error error=tracker announce error: Connection cookie error: cookie value is expired: -0.000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000010019048947253183, expected > 1744614199.079339 client_socket_addr=*.*.*.*:50075 server_socket_addr=0.0.0.0:6969 request_id=82473f7d-69ab-4377-bb13-8c4dbda3fd74 transaction_id=0

cookie value is from future

tracker  | 2025-04-14T07:05:20.185889Z ERROR process_request:handle_packet{server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id="216a95dc-9ced-4a90-80c0-6d0265ae82f1"}:handle_error{req_kind=Some(Announce) client_socket_addr=*.*.*.*:22169 server_service_binding=ServiceBinding { protocol: UDP, bind_address: 0.0.0.0:6969 } request_id=216a95dc-9ced-4a90-80c0-6d0265ae82f1 cookie_valid_range=1744614199.1857991..1744614321.1857991 e=UdpAnnounceError { source: ConnectionCookieError { source: ValueFromFuture { future_value: 2.856054034575238e191, max_value: 1744614321.1857991 } } }}: UDP TRACKER: response error error=tracker announce error: Connection cookie error: cookie value is from future: 285605403457523800000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1744614321.1857991 client_socket_addr=*.*.*.*:22169 server_socket_addr=0.0.0.0:6969 request_id=216a95dc-9ced-4a90-80c0-6d0265ae82f1 transaction_id=0

We implemented a filter to ban IPs making wrong requests, and we ban a lot of IPs:

Image

The bans last for 1 hour.

Since this is a very common error, logs are full of them, making it harder to identify other types of errors.

I would suggest changing the level to WARNING to prevent information overload.

josecelano avatar Apr 14 '25 08:04 josecelano