Overhaul stats: Wrong UDP Average Connect Time metric

[josecelano]

I've deployed the latest changes to the tracker demo and there is one bug in one of the metrics:

The problem may be that there are connection requests to a second UDP tracker (port 6868), but there are not announce and scrape requests.

# HELP udp_tracker_server_performance_avg_processing_time_ns Average time to process a UDP connect request in nanoseconds
# TYPE udp_tracker_server_performance_avg_processing_time_ns gauge
udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 18446743710713731000
udp_tracker_server_performance_avg_processing_time_ns{request_kind="scrape",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 40927.05282530009
udp_tracker_server_performance_avg_processing_time_ns{request_kind="announce",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 29331.002378199326
udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 18446743710604753000

Subtasks

• Fix the bug
• Fix also the problem described here.
• Refactor

[josecelano]

After the initial debug locally, the simplest case is working:

• Metrics endpoint: http://localhost:1212/api/v1/metrics?token=MyAccessToken&format=prometheus
• Command to simulate one connect and announce: cargo run -p torrust-tracker-client --bin udp_tracker_client announce udp://127.0.0.1:6969 000620bbc6c52d5a96d98f6c0f1dfa523a40df82 | jq

After one connect and announce (logs and metrics):

2025-06-17T17:49:00.356203Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 43732 ns (previous: 0 ns, req_processing_time: 43732 ns, udp_connections_handled: 1)
2025-06-17T17:49:00.356768Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average announce processing time: 498363 ns (previous: 0 ns, req_processing_time: 498363 ns, udp_announces_handled: 1)

udp_tracker_server_performance_avg_processing_time_ns{request_kind="announce",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 498363
udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 43732

After the second connect and announce (logs and metrics):

2025-06-17T17:51:46.448092Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 44283 ns (previous: 43732 ns, req_processing_time: 44834 ns, udp_connections_handled: 2)
2025-06-17T17:51:46.448277Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average announce processing time: 307104.5 ns (previous: 498363 ns, req_processing_time: 115846 ns, udp_announces_handled: 2)

udp_tracker_server_performance_avg_processing_time_ns{request_kind="announce",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 307104.5
udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 44283

After the third connect and announce (logs and metrics):

2025-06-17T17:59:24.713595Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 45485 ns (previous: 44283 ns, req_processing_time: 47889 ns, udp_connections_handled: 3)
2025-06-17T17:59:24.713832Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average announce processing time: 259902.66666666666 ns (previous: 307104 ns, req_processing_time: 165500 ns, udp_announces_handled: 3)

udp_tracker_server_performance_avg_processing_time_ns{request_kind="announce",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 259902.66666666666
udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 45485

(43732+44834+47889)÷3 = 45485
(498363+115846+165500)÷3 = 259903

[josecelano]

With two UDP trackers running on ports 6868 and 6969.

• http://localhost:1212/api/v1/stats?token=MyAccessToken&format=prometheus
• http://localhost:1212/api/v1/metrics?token=MyAccessToken&format=prometheus

cargo run -p torrust-tracker-client --bin udp_tracker_client announce udp://127.0.0.1:6868 000620bbc6c52d5a96d98f6c0f1dfa523a40df82 | jq

cargo run -p torrust-tracker-client --bin udp_tracker_client announce udp://127.0.0.1:6969 000620bbc6c52d5a96d98f6c0f1dfa523a40df82 | jq

After one connect and announce (logs and metrics) from tracker running on port 6868:

2025-06-17T18:46:30.529786Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 48691 ns (previous: 0 ns, req_processing_time: 48691 ns, udp_connections_handled: 1)
2025-06-17T18:46:30.529996Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average announce processing time: 131386 ns (previous: 0 ns, req_processing_time: 131386 ns, udp_announces_handled: 1)

udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 48691
udp_tracker_server_performance_avg_processing_time_ns{request_kind="announce",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 131386

After two connect and announce (logs and metrics) from tracker running on port 6969:

2025-06-17T18:47:24.091692Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 45976 ns (previous: 48691 ns, req_processing_time: 43261 ns, udp_connections_handled: 2)
2025-06-17T18:47:24.091802Z  INFO torrust_udp_tracker_server::statistics::repository: Recalculated UDP average announce processing time: 90063.5 ns (previous: 131386 ns, req_processing_time: 48741 ns, udp_announces_handled: 2)

udp_tracker_server_performance_avg_processing_time_ns{request_kind="announce",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 131386
udp_tracker_server_performance_avg_processing_time_ns{request_kind="announce",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 90063.5
udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6868",server_binding_protocol="udp"} 48691
udp_tracker_server_performance_avg_processing_time_ns{request_kind="connect",server_binding_address_ip_family="inet",server_binding_address_ip_type="plain",server_binding_ip="0.0.0.0",server_binding_port="6969",server_binding_protocol="udp"} 45976

Mean of final sample values:

(48691+43261)÷2 = 45976
(131386+48741)÷2 = 90063,5

Manually calculate the mean:

(48691+43261)÷2 = 45976
(131386+48741)÷2 = 90063,5

[josecelano]

I have more information after enabling additional debugging.

I run the tracker with this command to capture the output when the tracker starts:

./share/bin/deploy-torrust-demo.com.sh && ./share/bin/tracker-filtered-logs.sh >> 20250618_filtered_logs.txt   

Then, I've been analysing the logs with:

cat 20250618_filtered_logs.txt | grep "Recalculated UDP average conn" | head -n 8000

Or:

docker logs -f tracker | grep "Recalculated UDP average conn"

There are some things wrong:

1. The number of connection requests (needed to calculate the running moving average) does not increase every time the new average is calculated.

• Sometimes is the same
• Sometimes it is increased by more than one.

2. At some point in the logs, the new previous average does not appear in the previous log lines.
   In the following log capture, the average 10030480 does not exist in previous log lines.

tracker  | 2025-06-18T16:58:32.221472Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 418470.58635448135 ns (previous: 418446 ns, req_processing_time: 516103 ns, udp_connections_handled: 3972)
tracker  | 2025-06-18T16:58:32.224598Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 418394.1804681601 ns (previous: 418470 ns, req_processing_time: 117239 ns, udp_connections_handled: 3973)
tracker  | 2025-06-18T16:58:32.240866Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 418515.2249056604 ns (previous: 418394 ns, req_processing_time: 900263 ns, udp_connections_handled: 3975)
tracker  | 2025-06-18T16:58:32.251760Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 418420.8323278029 ns (previous: 418515 ns, req_processing_time: 43916 ns, udp_connections_handled: 3978)
tracker  | 2025-06-18T16:58:32.252238Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 418325.2745098039 ns (previous: 418420 ns, req_processing_time: 41602 ns, udp_connections_handled: 3978)
tracker  | 2025-06-18T16:58:32.290263Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 418227.4716080402 ns (previous: 418325 ns, req_processing_time: 30162 ns, udp_connections_handled: 3980)
tracker  | 2025-06-18T16:58:32.293483Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 418128.5149459935 ns (previous: 418227 ns, req_processing_time: 26158 ns, udp_connections_handled: 3981)
tracker  | 2025-06-18T16:58:32.294260Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 418062.3911077619 ns (previous: 418128 ns, req_processing_time: 156939 ns, udp_connections_handled: 3981)
tracker  | 2025-06-18T16:58:32.296808Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417966.33894049714 ns (previous: 418062 ns, req_processing_time: 37044 ns, udp_connections_handled: 3983)
tracker  | 2025-06-18T16:58:32.297177Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417867.43635450664 ns (previous: 417966 ns, req_processing_time: 25387 ns, udp_connections_handled: 3983)
tracker  | 2025-06-18T16:58:32.300308Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417787.6666666667 ns (previous: 417867 ns, req_processing_time: 101803 ns, udp_connections_handled: 3984)
tracker  | 2025-06-18T16:58:32.300890Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417688.2545180723 ns (previous: 417787 ns, req_processing_time: 24385 ns, udp_connections_handled: 3984)
tracker  | 2025-06-18T16:58:32.311997Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417982.6878293601 ns (previous: 417688 ns, req_processing_time: 1592019 ns, udp_connections_handled: 3985)
tracker  | 2025-06-18T16:58:32.335198Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417889.2301129235 ns (previous: 417982 ns, req_processing_time: 48294 ns, udp_connections_handled: 3985)
tracker  | 2025-06-18T16:58:32.336092Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417968.04466750316 ns (previous: 417889 ns, req_processing_time: 732882 ns, udp_connections_handled: 3985)
tracker  | 2025-06-18T16:58:32.337356Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417891.09157049673 ns (previous: 417968 ns, req_processing_time: 111411 ns, udp_connections_handled: 3986)
tracker  | 2025-06-18T16:58:32.344045Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417806.8018063221 ns (previous: 417891 ns, req_processing_time: 82277 ns, udp_connections_handled: 3986)
tracker  | 2025-06-18T16:58:32.345747Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 417721.7202709483 ns (previous: 417806 ns, req_processing_time: 81867 ns, udp_connections_handled: 3986)


tracker  | 2025-06-18T16:58:32.710031Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 10028002.57674188 ns (previous: 10030480 ns, req_processing_time: 39032 ns, udp_connections_handled: 4033)


tracker  | 2025-06-18T16:58:32.711995Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 10444527.66187407 ns (previous: 10447095 ns, req_processing_time: 90453 ns, udp_connections_handled: 4034)
tracker  | 2025-06-18T16:58:32.714475Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 10860963.405304909 ns (previous: 10863620 ns, req_processing_time: 146917 ns, udp_connections_handled: 4034)
tracker  | 2025-06-18T16:58:32.751010Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 11277290.748205 ns (previous: 11280056 ns, req_processing_time: 111204 ns, udp_connections_handled: 4039)
tracker  | 2025-06-18T16:58:32.751505Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 11693498.243377073 ns (previous: 11696383 ns, req_processing_time: 44851 ns, udp_connections_handled: 4039)
tracker  | 2025-06-18T16:58:32.752807Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 12109634.221589502 ns (previous: 12112590 ns, req_processing_time: 174201 ns, udp_connections_handled: 4039)
tracker  | 2025-06-18T16:58:32.753332Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 12525666.494924486 ns (previous: 12528726 ns, req_processing_time: 171385 ns, udp_connections_handled: 4039)
tracker  | 2025-06-18T16:58:32.755242Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 12941591.574610244 ns (previous: 12944759 ns, req_processing_time: 145193 ns, udp_connections_handled: 4041)
tracker  | 2025-06-18T16:58:32.758760Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 13357416.750618506 ns (previous: 13360684 ns, req_processing_time: 154462 ns, udp_connections_handled: 4042)
tracker  | 2025-06-18T16:58:32.760699Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 13773116.780059377 ns (previous: 13776509 ns, req_processing_time: 65156 ns, udp_connections_handled: 4042)
tracker  | 2025-06-18T16:58:32.762555Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 14188705.75296736 ns (previous: 14192209 ns, req_processing_time: 25078 ns, udp_connections_handled: 4044)
tracker  | 2025-06-18T16:58:32.764601Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 14604193.425216317 ns (previous: 14607798 ns, req_processing_time: 27293 ns, udp_connections_handled: 4045)
tracker  | 2025-06-18T16:58:32.778705Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 15020569.533860603 ns (previous: 15023286 ns, req_processing_time: 4032464 ns, udp_connections_handled: 4046)
tracker  | 2025-06-18T16:58:32.779471Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 15435859.663948603 ns (previous: 15439662 ns, req_processing_time: 51608 ns, udp_connections_handled: 4047)
tracker  | 2025-06-18T16:58:32.781198Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 15851045.223073123 ns (previous: 15854952 ns, req_processing_time: 40319 ns, udp_connections_handled: 4048)
tracker  | 2025-06-18T16:58:32.783367Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 16266129.41111111 ns (previous: 16270137 ns, req_processing_time: 39402 ns, udp_connections_handled: 4050)
tracker  | 2025-06-18T16:58:32.785532Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 16681143.487660415 ns (previous: 16685222 ns, req_processing_time: 159090 ns, udp_connections_handled: 4052)
tracker  | 2025-06-18T16:58:32.798683Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 17096259.7100271 ns (previous: 17100236 ns, req_processing_time: 960475 ns, udp_connections_handled: 4059)
tracker  | 2025-06-18T16:58:32.799394Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 17511044.220004927 ns (previous: 17515352 ns, req_processing_time: 30073 ns, udp_connections_handled: 4059)
tracker  | 2025-06-18T16:58:32.817389Z DEBUG torrust_udp_tracker_server::statistics::repository: Recalculated UDP average connect processing time: 17925768.966264468 ns (previous: 17930136 ns, req_processing_time: 195612 ns, udp_connections_handled: 4061)

I'm going to add more debug for when the metric is updated. However, I think the problem could be a race condition:

The new average calculation and writing the metric values are not done atomically!

I suppose that's the reason it's working locally, as I'm unable to reproduce that race condition easily.

This could be the change that introduced the bug:

packages/udp-tracker-server/src/statistics/repository.rs

In this PR.

The original method: https://github.com/josecelano/torrust-tracker/blob/a5c5a890a5af81ce1e01a978759ee42432d8490e/packages/udp-tracker-server/src/statistics/repository.rs#L106-L126

#[allow(clippy::cast_precision_loss)]
#[allow(clippy::cast_possible_truncation)]
#[allow(clippy::cast_sign_loss)]
pub async fn recalculate_udp_avg_announce_processing_time_ns(&self, req_processing_time: Duration) -> f64 {
    let mut stats_lock = self.stats.write().await;

    let req_processing_time = req_processing_time.as_nanos() as f64;

    let udp_announces_handled = (stats_lock.udp4_announces_handled + stats_lock.udp6_announces_handled) as f64;

    let previous_avg = stats_lock.udp_avg_announce_processing_time_ns;

    // Moving average: https://en.wikipedia.org/wiki/Moving_average
    let new_avg = previous_avg as f64 + (req_processing_time - previous_avg as f64) / udp_announces_handled;

    stats_lock.udp_avg_announce_processing_time_ns = new_avg.ceil() as u64;

    drop(stats_lock);

    new_avg
}

The new one: https://github.com/torrust/torrust-tracker/blob/develop/packages/udp-tracker-server/src/statistics/repository.rs#L76-L101

#[allow(clippy::cast_precision_loss)]
#[allow(clippy::cast_possible_truncation)]
#[allow(clippy::cast_sign_loss)]
pub async fn recalculate_udp_avg_connect_processing_time_ns(&self, req_processing_time: Duration) -> f64 {
    let stats_lock = self.stats.write().await;

    let req_processing_time = req_processing_time.as_nanos() as f64;
    let udp_connections_handled = (stats_lock.udp4_connections_handled() + stats_lock.udp6_connections_handled()) as f64;

    let previous_avg = stats_lock.udp_avg_connect_processing_time_ns();

    // Moving average: https://en.wikipedia.org/wiki/Moving_average
    let new_avg = previous_avg as f64 + (req_processing_time - previous_avg as f64) / udp_connections_handled;

    drop(stats_lock);

    tracing::debug!(
        "Recalculated UDP average connect processing time: {} ns (previous: {} ns, req_processing_time: {} ns, udp_connections_handled: {})",
        new_avg,
        previous_avg,
        req_processing_time,
        udp_connections_handled
    );

    new_avg
}

As you can see, the line:

stats_lock.udp_avg_announce_processing_time_ns = new_avg.ceil() as u64;

It's not there because it was moved to here.

I will:

• Add more debug lines and redeploy to the tracker demo to confirm this is the problem.
• Restore the previous atomic operation, but with the new labelled metrics. Calculate the new average and update the metric should be an atomic operation.

cc @da2ce7