Overhaul stats: UDP tracker core metrics don't match the corresponding UDP tracker server metrics

[josecelano]

I've deployed the new metrics to the Torrust Demo tracker.

We are emitting metrics from the:

• UDP Tracker Cerver
• UDP Tracker Core

Some metrics should have the same value. For example, the number of announce requests received. However, they don't match:

UDP tracker Core

udp_tracker_core_connect_requests_received_total{server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 1414

udp_tracker_core_announce_requests_received_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 9855098
udp_tracker_core_connect_requests_received_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 3085603
udp_tracker_core_scrape_requests_received_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 377400

UDP Tracker Server

udp_tracker_server_requests_received_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 66
udp_tracker_server_requests_banned_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 1

udp_tracker_server_requests_accepted_total{kind="announce",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 32
udp_tracker_server_requests_accepted_total{kind="connect",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 19

udp_tracker_server_responses_sent_total{kind="",result="ok",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 32
udp_tracker_server_responses_sent_total{kind="connect",result="ok",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 19

udp_tracker_server_errors_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 32
udp_tracker_server_performance_avg_connect_processing_time_ns{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 45029

Problems:

• udp_tracker_server_requests_received_total is fixed and low compared with any of the "received" counters in the UDP tracker core.
• The UDP tracker server is not generating metrics for the second tracker in port 6868.

Notes:

• It's weird that the server does not track the request, but the requests reach the track core.

It could be related to a bug described here. However, that bug should only affect the counters for sent responses.

I haven't been able to reproduce it locally yet.

How to run a manual test in development

1. Run the tracker
2. Use the tracker client to make requests

For example:

cargo run -p torrust-tracker-client --bin http_tracker_client announce http://127.0.0.1:7070 443c7602b4fde83d1154d6d9da48808418b181b6 | jq
cargo run -p torrust-tracker-client --bin http_tracker_client scrape http://127.0.0.1:7070 443c7602b4fde83d1154d6d9da48808418b181b6 | jq
cargo run -p torrust-tracker-client --bin udp_tracker_client announce udp://127.0.0.1:6969 443c7602b4fde83d1154d6d9da48808418b181b6 | jq
cargo run -p torrust-tracker-client --bin udp_tracker_client scrape udp://127.0.0.1:6969 443c7602b4fde83d1154d6d9da48808418b181b6 | jq

3. Load the metrics

JSON format:

curl "http://127.0.0.1:1212/api/v1/metrics?token=MyAccessToken&format=json" | jq

Prometheus format:

curl "http://127.0.0.1:1212/api/v1/metrics?token=MyAccessToken&format=prometheus" | sort

[josecelano]

I have fixed a bug with listeners that was causing the main problem. These are the metrics after running the tracker for some hours:

# 6969

# UDP Tracker Server 6969

udp_tracker_server_requests_received_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 147938532

udp_tracker_server_requests_banned_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 32588006

# Received - banned = 147938532 - 32588006 = 115350526

udp_tracker_server_requests_accepted_total{kind="connect",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 22515405
udp_tracker_server_requests_accepted_total{kind="announce",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 89616455
udp_tracker_server_requests_accepted_total{kind="scrape",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 2277329

# Total accepted = 22515405 + 89616455 + 2277329 = 114409189

# Total banned + accepted = 32588006 + 114409189 = 146997195

udp_tracker_server_requests_aborted_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 9510

udp_tracker_server_responses_sent_total{request_kind="connect",result="ok",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 22515381
udp_tracker_server_responses_sent_total{request_kind="announce",result="ok",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 86325399
udp_tracker_server_responses_sent_total{request_kind="scrape",result="ok",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 2257166
udp_tracker_server_responses_sent_total{result="error",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 4248840

# Total sent 115346786

# Total accepted connect - Total sent connect = 22515405 - 22515381 = 24
# Total accepted announce - Total sent announce = 89616455 - 86325399 = 3291056
# Total accepted scrape - Total sent scrape = 2277329 - 2257166 = 20163
# Total accepted - Total sent = 114409189 - 115346786 = −937597

udp_tracker_server_errors_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 4222856

udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 303613.98837337113
udp_tracker_server_performance_avg_processing_time_ns{request_kind="announce",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 3110734.972650558
udp_tracker_server_performance_avg_processing_time_ns{request_kind="scrape",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 300483.8935028711

# UDP Tracker Core 6969

udp_tracker_core_requests_received_total{request_kind="connect",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 22515405
udp_tracker_core_requests_received_total{request_kind="announce",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 86325399
udp_tracker_core_requests_received_total{request_kind="scrape",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 2257166

# 6868

# UDP Tracker Server 6868

udp_tracker_server_requests_received_total{server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 10213
udp_tracker_server_requests_accepted_total{kind="connect",server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 10213
udp_tracker_server_responses_sent_total{request_kind="connect",result="ok",server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 10213
udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 303603.98885954055

# UDP Tracker Core 6868

udp_tracker_core_requests_received_total{request_kind="connect",server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 10213

# 7070

HTTP Tracker Core

http_tracker_core_requests_received_total{request_kind="announce",server_binding_ip="0.0.0.0",server_binding_port="7070",server_binding_protocol="http"} 24

There are some strange things. For example, I would expect the total number of responses sent to be:

Total number of responses sent = requests accepted - requests aborted

But it's not. The reason could be one error I have described here. Some clients are using port 0 and the tracker can't send the response back.

[josecelano]

I analyzed with AI.

AI model: R1 | Lambda

---

Here's an analysis of the provided Prometheus metrics, highlighting potential issues and anomalies:

1. Discrepancy Between Received and Accounted Requests (Port 6969)

• Total Received: 147,938,532
• Accounted For:
  • Banned: 32,588,006
  • Accepted: 114,409,189
  • Aborted: 9,510
  • Total Accounted: 32,588,006 + 114,409,189 + 9,510 = 147,006,705
• Missing Requests: 147,938,532 - 147,006,705 = ~931,827
  • Issue: ~931k requests are unaccounted for. These might be dropped due to malformed packets, network issues, or metric reporting errors.

---

2. Response Count Exceeds Accepted Requests (Port 6969)

• Total Accepted Requests: 114,409,189
• Total Responses Sent: 115,346,786
• Discrepancy: +937,597 (responses > requests).
  • Possible Causes:
    • Duplicate responses (e.g., retries/timeouts).
    • Mislabeled metrics (e.g., responses sent for banned requests).
    • Race conditions in counters (e.g., responses counted before requests).

---

3. "Accepted" vs. Core "Received" Mismatch (Port 6969)

• Announce Requests:
  • Server Accepted: 89,616,455
  • Core Received: 86,325,399
  • Difference: -3,291,056
• Scrape Requests:
  • Server Accepted: 2,277,329
  • Core Received: 2,257,166
  • Difference: -20,163
• Issue: The server counts requests as "accepted," but the core (business logic) does not receive them. This mismatch could indicate:
  • Requests failing validation after initial acceptance.
  • Resource exhaustion (e.g., dropped due to backpressure).
  • Metric labeling inconsistencies.

---

4. Error Metric Inconsistencies (Port 6969)

• udp_tracker_server_errors_total: 4,222,856
• Error Responses (result="error"): 4,248,840
• Difference: +25,984
  • Possible Causes: Errors might be double-counted in responses, or some errors not logged in server_errors_total.

---

5. HTTP Tracker Anomaly

• HTTP Core Requests (Port 7070): Only 24 announce requests.
  • Red Flag: No corresponding server metrics (e.g., http_tracker_server_requests_received_total). Either HTTP metrics are incomplete, or the server component isn't instrumented.

---

6. Port 6868 Inconsistencies

• UDP Tracker on 6868:
  • All connect requests (10,213) are accepted, sent as responses, and received by the core. This matches expectations, but the lack of other request types (announce/scrape) may indicate limited usage or misconfiguration.

---

Other Observations

• Average Processing Times: Appear reasonable for UDP:
  • connect: ~0.3 ms
  • announce: ~3.1 ms (more complex, as expected).
  • scrape: ~0.3 ms.
• Binding Labels: All metrics use server_binding_ip="0.0.0.0" (wildcard IP), which is normal for listeners but could mask issues in multi-homed environments.

---

Recommendations

1. Investigate Unaccounted Requests (931k gap): Check for metric gaps (e.g., pending requests, malformed packets).
2. Audit Response Counting Logic: Ensure responses map 1:1 to requests. Look for retries or mislabeled error responses.
3. Trace Request Flow from Server to Core: Diagnose why some accepted requests don’t reach the core (logs, failures during processing).
4. Validate Error Metrics: Align server_errors_total with error responses for consistency.
5. Add HTTP Server Metrics: Ensure all components (HTTP/UDP) report metrics consistently.

The anomalies suggest either bugs in metric instrumentation (e.g., double-counting, mislabeling) or deeper issues in request processing (e.g., silent request drops after acceptance).

[josecelano]

The difference between accepted and sent is because the "accepted" ones are the ones the tracker can parse. There are some "bad requests" that can't be parsed but the tracker sends an error response. Maybe we should include that a new kind:

udp_tracker_server_requests_accepted_total{kind="connect",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 22515405
udp_tracker_server_requests_accepted_total{kind="announce",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 89616455
udp_tracker_server_requests_accepted_total{kind="scrape",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 2277329

udp_tracker_server_parse_requests_errors_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 2277329

cc @da2ce7

[josecelano]

The difference between accepted and sent is because the "accepted" ones are the ones the tracker can parse. There are some "bad requests" that can't be parsed but the tracker sends an error response. Maybe we should include that a new kind:

udp_tracker_server_requests_accepted_total{kind="connect",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 22515405
udp_tracker_server_requests_accepted_total{kind="announce",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 89616455
udp_tracker_server_requests_accepted_total{kind="scrape",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 2277329

udp_tracker_server_parse_requests_errors_total{server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 2277329

cc @da2ce7

Instead of adding a new error, I have added a new label request_kind to the udp_tracker_server_parse_requests_errors_total metric. When the label is missing, that means it was not possible to parse the request.