Report call route queues and ACK progress at 200ms cadence

src/call/call.c

@@ -539,16 +539,6 @@ static void call_post_stats(struct call_session* s) {
                 (unsigned long long)s->call_id, s->tx_wait_frames, s->tx_q ? (size_t)queue_entry_count(s->tx_q) : 0, oldest_ms,
                 (unsigned long long)(s->tx_wait_frames ? s->tx_wait_total_ms / s->tx_wait_frames : 0), s->tx_wait_max_ms);
     s->tx_wait_frames = s->tx_wait_max_ms = 0; s->tx_wait_total_ms = 0;
-    struct ETCP_ROUTER_TX_STATS net = {0};
-    etcp_router_tx_stats(ctx->inst, s->group_id, s->peer_node_id, ETCP_RT_ID_CALL_AUDIO, get_time_us(), &net);
-    const char *wait = s->tx_q && s->tx_q->count < (int)s->audio_batch.target ? "frames"
-        : !s->audio_send.conn ? "unregistered" : net.no_route ? "no-route" : !net.ready ? "handshake"
-        : net.receive_busy ? "peer-busy" : rconn && net.inflight_packets >= rconn->inflight_limit ? "window" : "transport";
-    DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "audio batch flow call=%llx target=%u wait=%s queued=%u/%llu inflight=%u/%llu "
-                "enqueue_ack_us=%llu submit_ack_us=%u ack_bytes_500ms=%llu tx_frames=%u tx_batches=%u rx_frames=%u rx_batches=%u",
-                (unsigned long long)s->call_id, s->audio_batch.target, wait, net.queued_packets, (unsigned long long)net.queued_age_us,
-                net.inflight_packets, (unsigned long long)net.inflight_age_us, (unsigned long long)net.delivery_rtt_us,
-                net.rtt_us, (unsigned long long)net.window.bytes, s->c_tx_frames, s->tx_batches, s->c_rx_frames, s->rx_batches);
     call_tx_flush(s); /* Повтор регистрации после reset/ошибки выделения; обычный drain работает по событиям. */
     DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "%s: stats id=%016llx recv_peer=%016llx rtt_tb=%u rtt_ms=%u buffer=%dms tempo=%d dropped=%u underruns=%u",
                 CALL_ID, (unsigned long long)s->call_id,
@@ -1014,6 +1004,35 @@ static void call_audio_batch_tick(void* arg) {
     struct ETCP_ROUTER_TX_STATS net = {0};
     uint64_t now = get_time_us();
     int found = etcp_router_tx_stats(s->ctx->inst, s->group_id, s->peer_node_id, ETCP_RT_ID_CALL_AUDIO, now, &net) == 0;
+    if (now - s->buffer_log_us >= CALL_BUFFER_LOG_MS * 1000) {
+        uint64_t elapsed = s->buffer_log_us ? now - s->buffer_log_us : 0; s->buffer_log_us = now;
+        if (debug_should_output(DEBUG_LEVEL_DEBUG, DEBUG_CATEGORY_CALL)) {
+            struct ETCP_ROUTER_CONN* r = s->audio_send.conn;
+            uint64_t oldest_us = s->tx_q && s->tx_q->head
+                ? now - ((struct call_audio_pending*)s->tx_q->head->data)->created_us : 0;
+            const char* wait = !s->tx_q || !s->tx_q->count ? "empty" : s->tx_q->count < (int)s->audio_batch.target ? "frames"
+                : !found ? "no-channel" : net.no_route ? "no-route" : !net.ready ? "handshake"
+                : net.receive_busy ? "peer-busy" : r && net.inflight_packets >= r->inflight_limit ? "window"
+                : !r ? "unregistered" : "router-or-transport";
+            DEBUG_DEBUG(DEBUG_CATEGORY_CALL,
+                "audio transport call=%016llx mono_ms=%llu dt_ms=%llu batch=%u feedback=%d delay_ms=%.1f wait=%s "
+                "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",
+                (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,
+                found, net.ready, net.no_route, net.receive_busy, net.probing,
+                net.queued_packets, (unsigned long long)net.queued_bytes, net.queued_age_us / 1000.0,
+                net.inflight_packets, (unsigned long long)net.inflight_bytes, net.inflight_age_us / 1000.0,
+                net.delivery_rtt_us / 1000.0, net.rtt_us / 1000.0, net.baseline_rtt_us / 1000.0,
+                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));
+        }
+    }
     const struct call_audio_ops* audio = s->ctx->inst->call_audio_ops;
     if (audio && audio->record_tx) {
         struct call_history_tx snapshot = {.at_ms = now / 1000, .queued_bytes = s->tx_q ? s->tx_q->total_bytes : 0};

src/call/call_priv.h

@@ -37,6 +37,7 @@ struct call_session {
     uint16_t tx_media_seq;         /* Следующий sequence аудиопакета с wrap uint16; расходуется до выделения TX entry. */
     struct call_audio_batch_control audio_batch; /* Прежний адаптивный выбор обязательного числа кадров. */
     void *audio_batch_timer; /* Снимок Router и пересчёт target каждые 50мс; не отправляет неполную пачку. */
+    uint64_t buffer_log_us; /* Последняя сводка транспорта, монотонные мкс; период 200мс, без отдельного таймера. */
     uint32_t tx_batches, rx_batches; /* Число Router-кодограмм, отдельно от аудиокадров. */
     struct ll_queue *tx_q;         /* FIFO Opus с локальными seq/PTS/created_us в entry->data; до 750, overflow удаляет голову. */
     struct router_send_request audio_send; /* Слот отправки: до callback кадры остаются в tx_q. */