Verify diagnostic cadence, filtering and full buffer log delivery

src/call/call.c

@@ -1019,7 +1019,7 @@ static void call_audio_batch_tick(void* arg) {
                 "local_frames=%u local_B=%llu local_age_ms=%.1f router_found=%d ready=%d no_route=%d busy=%d probing=%d "
                 "queued_pkts_B=%u/%llu queued_age_ms=%.1f inflight_pkts_B=%u/%llu inflight_age_ms=%.1f "
                 "enqueue_ack_ms=%.1f submit_ack_ms=%.1f baseline_ms=%.1f ack_age_ms=%.1f ack_B_500ms=%llu "
-                "epochs=%llu/%llu tx_frames_batches=%u/%u rx_frames_batches=%u/%u tx_dropped_total=%u rx_idle_ms=%llu",
+                "epochs=%llu/%llu tx_frames_batches=%u/%u rx_frames_batches=%u/%u tx_dropped_total=%u rx_idle_ms=%lld",
                 (unsigned long long)s->call_id, (unsigned long long)(now / 1000), (unsigned long long)(elapsed / 1000),
                 s->audio_batch.target, s->audio_batch.feedback_received, s->audio_batch.delay_us / 1000.0, wait,
                 s->tx_q ? (unsigned)s->tx_q->count : 0, (unsigned long long)(s->tx_q ? s->tx_q->total_bytes : 0), oldest_us / 1000.0,
@@ -1030,7 +1030,7 @@ static void call_audio_batch_tick(void* arg) {
                 net.last_ack_us ? (now - net.last_ack_us) / 1000.0 : -1.0, (unsigned long long)net.window.bytes,
                 (unsigned long long)net.local_epoch, (unsigned long long)net.peer_epoch,
                 s->c_tx_frames, s->tx_batches, s->c_rx_frames, s->rx_batches, s->c_tx_dropped,
-                (unsigned long long)((get_time_tb() - s->last_media_tb) / 10));
+                s->last_media_tb ? (long long)((get_time_tb() - s->last_media_tb) / 10) : -1ll);
         }
     }
     const struct call_audio_ops* audio = s->ctx->inst->call_audio_ops;

tools/chatgui/tests/test_call_jitter.cpp

@@ -196,6 +196,34 @@ static void test_render_readiness() {
     call_audio_release(id); opus_codec_encoder_destroy(enc);
 }
 
+static unsigned buffer_logs;
+static void capture_buffer_log(int level, const char* category, const char* message) {
+    if (std::strstr(message, "audio buffers call=")) {
+        CHECK(level == DEBUG_LEVEL_DEBUG && !std::strcmp(category, "call"));
+        CHECK(std::strstr(message, "missing_ms=") && std::strstr(message, "wire_Bps="));
+        CHECK(std::strstr(message, "aec_over_under_total=")); // Конец строки тоже дошёл до выхода.
+        ++buffer_logs;
+    }
+}
+
+static void test_audio_buffer_logs() {
+    CHECK(call_audio_start(900) == 0);
+    uint64_t base = get_time_us() / 1000;
+    auto previous = g_debug_config.category_levels[DEBUG_CATEGORY_CALL];
+    debug_set_category_level(DEBUG_CATEGORY_CALL, DEBUG_LEVEL_DEBUG); debug_set_log_hook(capture_buffer_log);
+    buffer_logs = 0;
+    for (unsigned offset : {200, 250, 350, 400}) {
+        call_history_tx tx{}; tx.at_ms = base + offset;
+        audio_owner.call_audio_ops->record_tx(900, &tx);
+    }
+    CHECK(buffer_logs == 2); // 50мс тики не превращаются в 20 строк в секунду.
+    debug_set_category_level(DEBUG_CATEGORY_CALL, DEBUG_LEVEL_INFO);
+    call_history_tx tx{}; tx.at_ms = base + 600; audio_owner.call_audio_ops->record_tx(900, &tx);
+    CHECK(buffer_logs == 2);
+    debug_set_log_hook(nullptr); debug_set_category_level(DEBUG_CATEGORY_CALL, previous);
+    call_audio_stop();
+}
+
 static void test_audio_history() {
     CallHistoryStore history;
     call_audio_history snapshot;
@@ -262,6 +290,7 @@ int main() {
     test_startup_policy();
     test_packet_arrival_sampling();
     CHECK(call_audio_init(&audio_owner) == 0);
+    test_audio_buffer_logs();
     test_render_readiness();
     {
         call_jitter_window w;