diff --git a/daemon/codec.c b/daemon/codec.c index 68fd50e71..ff34d066b 100644 --- a/daemon/codec.c +++ b/daemon/codec.c @@ -4061,6 +4061,8 @@ static void __dtx_send_later(struct codec_timer *ct) { rwlock_lock_r(&call->master_lock); __ssrc_lock_both(&mp_copy); + mp_copy.dtx = true; + if (dtxp) { ilogs(dtx, LOG_DEBUG, "Decoding DTX-buffered RTP packet (TS %lu) now; " "%i packets left in queue", ts, p_left); @@ -4100,8 +4102,6 @@ static void __dtx_send_later(struct codec_timer *ct) { mutex_unlock(&dtxb->lock); } } - if (ch && ch->encoder && mp_copy.ssrc_out) - mp_copy.ssrc_out->ts_out = ch->encoder->next_pts + ch->csch.first_ts; mutex_lock(&dtxb->lock); @@ -4726,6 +4726,15 @@ static void packet_encoded_tx(struct codec_ssrc_handler *ch, struct media_packet if (!repeats) break; } while (repeats--); + + // Save the clock of the actual output encoder for DTX restarts. The DTX decoder + // may run at a different rate and cannot supply the timestamp for this listener. + // Ordinary transcoding must retain the input timestamp origin when reconfigured. + if (mp->dtx && !is_dtmf) { + mp->ssrc_out->ts_out = ch->csch.first_ts + fraction_divl(pts + duration, cr_fact); + mp->ssrc_out->ts_out_time = rtpe_now + + fraction_divl(duration, cr_fact) * 1000000LL / ch->handler->dest_pt.clock_rate; + } } @@ -4923,8 +4932,14 @@ static tc_code packet_decode(struct codec_ssrc_handler *ch, struct codec_ssrc_ha { tc_code ret = TCC_OK; - if (!ch->csch.first_ts) + if (!ch->csch.first_ts) { ch->csch.first_ts = mp->ssrc_out->ts_out ?: packet->ts; + // A stopped encoder does not produce samples while prompts or floor + // blocking are active. Keep that elapsed time in the listener's RTP clock. + if (mp->ssrc_out->ts_out_time && rtpe_now > mp->ssrc_out->ts_out_time) + ch->csch.first_ts += (rtpe_now - mp->ssrc_out->ts_out_time) + * ch->handler->dest_pt.clock_rate / 1000000; + } if (ch->decoder && ch->decoder->def->dtmf) { if (packet_dtmf_event(ch, input_ch, packet, mp) == -1) diff --git a/include/media_socket.h b/include/media_socket.h index 7817118b5..f7fd7c716 100644 --- a/include/media_socket.h +++ b/include/media_socket.h @@ -313,6 +313,7 @@ struct media_packet { struct sink_handler sink; struct media_player_cache_entry *cache_entry; bool recording_egress; + bool dtx; // processed by the DTX timer; retain the output encoder clock struct rtp_header *rtp; struct rtcp_packet *rtcp; diff --git a/include/ssrc.h b/include/ssrc.h index 66087ba1b..6094a9739 100644 --- a/include/ssrc.h +++ b/include/ssrc.h @@ -53,6 +53,7 @@ struct ssrc_entry_call { uint32_t ssrc_map_out; uint16_t seq_out; unsigned long ts_out; + int64_t ts_out_time; // wall clock corresponding to the next output RTP timestamp bool seq_set; // RTCP stats diff --git a/t/Makefile b/t/Makefile index db85b9593..feb2e9cdc 100644 --- a/t/Makefile +++ b/t/Makefile @@ -90,7 +90,7 @@ include ../lib/common.Makefile daemon-tests-bundle daemon-tests-dtls daemon-tests-rollback \ daemon-tests-rollback-redis daemon-tests-redis-srtp-index \ daemon-tests-recording daemon-tests-create daemon-tests-created-subscriptions daemon-tests-alias \ - daemon-tests-kernel-api \ + daemon-tests-kernel-api daemon-tests-dtx-clock \ daemon-tests-video daemon-tests-inject daemon-tests-dtx-dtmf TESTS := test-bitstr aes-crypt aead-aes-crypt test-const_str_hash.strhash @@ -143,7 +143,7 @@ daemon-tests: daemon-tests-main daemon-tests-jb daemon-tests-pubsub daemon-tests daemon-tests-bundle daemon-tests-dtls daemon-tests-rollback daemon-tests-rollback-redis \ daemon-tests-redis-srtp-index \ daemon-tests-recording daemon-tests-create daemon-tests-created-subscriptions \ - daemon-tests-dtx daemon-tests-dtx-cn daemon-tests-dtx-no-shift daemon-tests-dtx-dtmf \ + daemon-tests-dtx daemon-tests-dtx-cn daemon-tests-dtx-no-shift daemon-tests-dtx-dtmf daemon-tests-dtx-clock \ daemon-tests-alias \ daemon-tests-kernel-api \ daemon-tests-video daemon-tests-inject @@ -184,6 +184,9 @@ daemon-tests-dtx: daemon-test-deps daemon-tests-dtx-dtmf: daemon-test-deps ./auto-test-helper "$@" perl -I../perl auto-daemon-tests-dtx-dtmf.pl +daemon-tests-dtx-clock: daemon-test-deps + ./auto-test-helper "$@" perl -I../perl auto-daemon-tests-dtx-clock.pl + daemon-tests-dtx-no-shift: daemon-test-deps ./auto-test-helper "$@" perl -I../perl auto-daemon-tests-dtx-no-shift.pl diff --git a/t/auto-daemon-tests-dtx-clock.pl b/t/auto-daemon-tests-dtx-clock.pl new file mode 100644 index 000000000..fef1cc9a4 --- /dev/null +++ b/t/auto-daemon-tests-dtx-clock.pl @@ -0,0 +1,129 @@ +#!/usr/bin/perl + +use strict; +use warnings; +use NGCP::Rtpengine::Test; +use NGCP::Rtpclient::SRTP; +use NGCP::Rtpengine::AutoTest; +use Test::More; + +# Repeated floor bursts must retain each output encoder clock through prompt playback. +autotest_start(qw(--config-file=none -t -1 -i 203.0.113.1 + -n 2223 -f -L 7 -E --silence-detect=1 --dtx-delay=50 --max-dtx=1)) or die; + +use Time::HiRes qw(time sleep); +use IO::Select; + +# Exercise equal rates, different RTP rates, and the G.722 sample/RTP rate factor. +for my $profile ( + ['PCMA/8000', 8, 8000, 100000], + ['opus/48000/2', 96, 48000, 100000], + ['G722/8000', 9, 8000, 0xfffff000], +) { + my ($codec, $pt, $rate, $origin) = @$profile; + my $offer_pts = $pt == 96 ? '96 97' : $pt; + my $offer_attrs = "a=rtpmap:$pt $codec"; + if ($pt == 96) { + $offer_attrs .= "\na=fmtp:96 useinbandfec=1\na=rtpmap:97 telephone-event/48000\na=fmtp:97 0-15"; + } + my ($sock_a, $sock_b) = new_call([qw(198.51.100.10 5000)], [qw(198.51.100.10 5002)]); + my $name = "DTX output clock across playback: $codec"; + + my ($port_a) = offer($name, { codec => { transcode => [$codec] } }, <new($sock_b); + my $end = time() + 0.3; + my $received = 0; + while (time() < $end && $sel->can_read(0.1)) { + my $p; + $sock_b->recv($p, 65535); + my ($out_pt, $q, $ts, $ssrc) = unpack('x C n N N', $p); + is($out_pt & 0x7f, $pt, 'burst uses the negotiated output codec'); + $audio_ssrc //= $ssrc; + is($ssrc, $audio_ssrc, 'speech SSRC survives playback transitions'); + my $now = time(); + if (defined $last_ts) { + my $delta = ($ts - $last_ts) & 0xffffffff; + cmp_ok($delta, '<', 0x80000000, 'output clock does not rewind'); + if ($now - $last_time > 1) { + # Receive after sending a 200 ms batch; allow that batching skew. + cmp_ok(abs($delta / $rate - ($now - $last_time)), '<', 0.3, + 'RTP clock includes elapsed playback and silence'); + } + } + $last_ts = $ts; + $last_time = $now; + $received++; + } + cmp_ok($received, '>=', 10, 'each burst produces output promptly'); + rtpe_req('block media', $name, {'from-tag' => ft(), flags => ['directional']}); + rtpe_req('play media', $name, {'from-tag' => tt(), blob => $wav}); + sleep(0.2); + rtpe_req('stop media', $name, {'from-tag' => tt()}); + while ($sel->can_read(0.01)) { + my $p; + $sock_b->recv($p, 65535); + } + sleep(1.4); + rtpe_req('unblock media', $name, {'from-tag' => ft(), flags => ['directional']}); + } + rtpe_req('delete', $name, {'from-tag' => ft()}); +} + +done_testing(); diff --git a/t/auto-daemon-tests-dtx.pl b/t/auto-daemon-tests-dtx.pl index e25e5e82e..c34982d37 100755 --- a/t/auto-daemon-tests-dtx.pl +++ b/t/auto-daemon-tests-dtx.pl @@ -22,7 +22,7 @@ my ($sock_a, $sock_b, $sock_c, $sock_d, $port_a, $port_b, $ssrc, $ssrc_b, $resp, $sock_ax, $sock_bx, $port_ax, $port_bx, $srtp_ctx_a, $srtp_ctx_b, $srtp_ctx_a_rev, $srtp_ctx_b_rev, - @ret1, @ret2, @ret3, @ret4, $srtp_key_a, $srtp_key_b, $ts, $seq); + @ret1, @ret2, @ret3, @ret4, $srtp_key_a, $srtp_key_b, $ts, $seq, $resume_time); @@ -705,10 +705,13 @@ rcv($sock_b, $port_a, rtpm(96, $seq + 10, 7200, 0x5678, "\xf0\x1c\x50\x54\x30\x77\xf3\xdd\x1d\xd3\x57\x6b\xce\xc7\xcd\x7a\x17\x71\x05\x36\x04\x42\x70\x72\x73\x25\x0c\x14\x26\x2a\x05\x72\x03\x90\xf2\x5c\x48\xd8")); # inject old PCM +$resume_time = Time::HiRes::time(); snd($sock_a, $port_b, rtp(0, 2004, 5120, 0x5678, "\x40" x 160)); snd($sock_a, $port_b, rtp(0, 2006, 5440, 0x5678, "\x40" x 160)); # packet dropped rcv_no($sock_b); +# Make the elapsed gap large enough to distinguish it from a single 20 ms increment. +Time::HiRes::usleep(200000); # reinvite back to PCMU @@ -762,9 +765,12 @@ snd($sock_a, $port_b, rtp(0, 2007, 5760, 0x5678, "\x40" x 160)); -rcv($sock_b, $port_a, rtpm(96, $seq + 11, 7520, $ssrc, "\xf0\x1c\x21\x40\x00\xff\xfb\xfc\x92\x17\x2f\x21\x34\xcb\x60\x28\x1b\x23\x23\x30\x04\x87\xb1\x30\x4f\x91\x04\x5e\xd9\xc6\x6c\xfc\x28\xed\xe1\xc6\xd5\xe0")); +# AMR-WB uses a 16 kHz output clock, independently of the G.711 input origin. +($ts) = rcv($sock_b, $port_a, rtpm(96, $seq + 11, -1, $ssrc, "\xf0\x1c\x21\x40\x00\xff\xfb\xfc\x92\x17\x2f\x21\x34\xcb\x60\x28\x1b\x23\x23\x30\x04\x87\xb1\x30\x4f\x91\x04\x5e\xd9\xc6\x6c\xfc\x28\xed\xe1\xc6\xd5\xe0")); +cmp_ok(abs(($ts - 7200) / 16000 - (Time::HiRes::time() - $resume_time)), '<', 0.1, + 'AMR-WB output clock advances through codec reconfiguration'); snd($sock_a, $port_b, rtp(0, 2007, 5920, 0x5678, "\x40" x 160)); -rcv($sock_b, $port_a, rtpm(96, $seq + 12, 7840, $ssrc, "\xf0\x1c\xc8\xc6\x04\x55\x92\x65\x07\x9c\x21\x19\x06\x71\x89\xd4\x66\xe6\x84\xe6\xc5\xc4\xc4\xcc\x5e\xc1\xc5\xf5\x4c\x55\xde\x71\x9a\x57\xc0\xde\xe4\xd0")); +rcv($sock_b, $port_a, rtpm(96, $seq + 12, $ts + 320, $ssrc, "\xf0\x1c\xc8\xc6\x04\x55\x92\x65\x07\x9c\x21\x19\x06\x71\x89\xd4\x66\xe6\x84\xe6\xc5\xc4\xc4\xcc\x5e\xc1\xc5\xf5\x4c\x55\xde\x71\x9a\x57\xc0\xde\xe4\xd0")); rtpe_req('delete', 'G.711/AMR-WB codec change reverse', { 'from-tag' => ft() }); @@ -894,6 +900,7 @@ rcv($sock_b, $port_a, rtpm(8, $seq + 10, 5600, 0x5678, "\xd5\xd5\xd5\xd5\x55\x55\xd5\x55\x55\xd5\x55\x55\x55\x55\xd5\x55\x55\xd5\x55\xd5\x55\xd5\x55\x55\xd5\xd5\xd5\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\xd5\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\xd5\x55\x55\xd5\x55\x55\x55\x55\x55\x55\x55\xd5\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\xd5\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\xd5\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\x55\xd5\xd5\xd5\xd5\xd5\xd5\xd5\x55\x55\x55\x55\x55\x55\x55")); # inject old PCM +$resume_time = Time::HiRes::time(); snd($sock_a, $port_b, rtp(0, 2006, 5760, 0x5678, "\x40" x 160)); # packet dropped rcv_no($sock_b); @@ -947,9 +954,12 @@ snd($sock_a, $port_b, rtp(0, 2007, 5920, 0x5678, "\x40" x 160)); -rcv($sock_b, $port_a, rtpm(8, $seq + 11, 5760, $ssrc, "\x68" x 160)); +# Reconfiguration retains elapsed time in the output clock, independently of the input origin. +($ts) = rcv($sock_b, $port_a, rtpm(8, $seq + 11, -1, $ssrc, "\x68" x 160)); +cmp_ok(abs(($ts - 5600) / 8000 - (Time::HiRes::time() - $resume_time)), '<', 0.1, + 'output clock advances through codec reconfiguration'); snd($sock_a, $port_b, rtp(0, 2008, 6080, 0x5678, "\x40" x 160)); -rcv($sock_b, $port_a, rtpm(8, $seq + 12, 5920, $ssrc, "\x68" x 160)); +rcv($sock_b, $port_a, rtpm(8, $seq + 12, $ts + 160, $ssrc, "\x68" x 160)); rtpe_req('delete', 'G.711/AMR-WB codec change with timing', { 'from-tag' => ft() }); @@ -1081,6 +1091,7 @@ rcv($sock_b, $port_a, rtpm(8, $seq + 10, 5600, 0x5678, "\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5\xd5")); # inject old PCM +$resume_time = Time::HiRes::time(); snd($sock_a, $port_b, rtp(0, 2006, 5600, 0x5678, "\x40" x 160)); # packet dropped rcv_no($sock_b); @@ -1134,7 +1145,10 @@ snd($sock_a, $port_b, rtp(0, 2007, 5760, 0x5678, "\x40" x 160)); -rcv($sock_b, $port_a, rtpm(8, $seq + 11, 5760, $ssrc, "\x68" x 160)); +# Reconfiguration retains elapsed time in the output clock, independently of the input origin. +($ts) = rcv($sock_b, $port_a, rtpm(8, $seq + 11, -1, $ssrc, "\x68" x 160)); +cmp_ok(abs(($ts - 5600) / 8000 - (Time::HiRes::time() - $resume_time)), '<', 0.1, + 'output clock advances through codec reconfiguration'); rtpe_req('delete', 'G.711/AMR codec change with timing', { 'from-tag' => ft() }); @@ -2044,14 +2058,17 @@ rcv($sock_b, $port_a, rtpm(8, $seq + 9 + $i, 5440 + $i * 160, $ssrc, "\xd5" x 160)); } # now shut down +$resume_time = Time::HiRes::time(); rcv_no($sock_b); # start audio again snd($sock_a, $port_b, rtp(0, 2005, 90000, 0x5678, "\x40" x 160)); -rcv($sock_b, $port_a, rtpm(8, $seq + 507, 90000, $ssrc, "\x68" x 160)); +($ts) = rcv($sock_b, $port_a, rtpm(8, $seq + 507, -1, $ssrc, "\x68" x 160)); +cmp_ok(abs(($ts - (5440 + 497 * 160)) / 8000 - (Time::HiRes::time() - $resume_time)), '<', 0.1, + 'output clock survives maximum DTX shutdown'); snd($sock_a, $port_b, rtp(0, 2006, 90160, 0x5678, "\x40" x 160)); -rcv($sock_b, $port_a, rtpm(8, $seq + 508, 90160, $ssrc, "\x68" x 160)); +rcv($sock_b, $port_a, rtpm(8, $seq + 508, $ts + 160, $ssrc, "\x68" x 160)); # DTX -> silence -rcv($sock_b, $port_a, rtpm(8, $seq + 509, 90320, $ssrc, "\xd5" x 160)); +rcv($sock_b, $port_a, rtpm(8, $seq + 509, $ts + 320, $ssrc, "\xd5" x 160)); rtpe_req('delete', 'G.711 DTX ptime change', { 'from-tag' => ft() });