From da1b4839ea4f38584ac2208696a79517feeeb59c Mon Sep 17 00:00:00 2001 From: evgeny Date: Fri, 30 Oct 2026 21:48:43 +0100 Subject: [PATCH] Verify diagnostic cadence, filtering and full buffer log delivery --- src/call/call.c | 4 ++-- tools/chatgui/tests/test_call_jitter.cpp | 29 ++++++++++++++++++++++++ 2 files changed, 31 insertions(+), 2 deletions(-) diff --git a/src/call/call.c b/src/call/call.c index d17ea0b5e..b9c962066 100644 --- a/src/call/call.c +++ b/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; diff --git a/tools/chatgui/tests/test_call_jitter.cpp b/tools/chatgui/tests/test_call_jitter.cpp index c1bc136ea..488f4b212 100644 --- a/tools/chatgui/tests/test_call_jitter.cpp +++ b/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;