Strange timestamp wrapping when using timerfd at each talkspurt

[davehorton]

Describe the bug
We recently added this line to our dialplan

<action application="set" data="timer_name=timerfd"/>

(Note: I will show the full dialplan below)

After doing so we started to receive reports of customers experiencing clipping on every playback command that we did. We took packet captures and we noticed a significant difference when this dialplan command is added.

Specifically, with this change, we see the timestamp value wrap in the RTP packet containing the Marker bit at the start of a play command. We remove this line, and we do not see this behavior with regards the timestamp (and the customer no longer experiences clipping). Note that the SSRC value is not changing (which would be a legitimate reason for the timestamp to jump or wrap), and the timestamp value was not so large that it needed to wrap, yet it did. And the downstream customer then experiences clipping at the beginning of each prompt.

I have shared a link to a pcap file below showing an example RTP stream generated by Freeswitch that illustrates this behavior.

Please note the following occurrences:

frame 47: timestamp rolls from 7040 to 320
frame 104: timestamp jumps from 9280 to 16160
frame 107: timestamp rolls from 16480 to 320

All of these occur are when the Marker bit is set. And again, if we remove that dialplan line this does not happen.

Here is the complete dialplan with the line added (when we hear clipping)

<action application="answer"/>
<action application="set" data="timer_name=timerfd"/>
<action application="set" data="send_silence_when_idle=-1"/>
<action application="set" data="hangup_after_bridge=false"/>
<action application="set" data="park_after_bridge=true"/>
<action application="set" data="playback_terminators=none"/>
<action application="socket" data="${sip_h_X-esl-outbound} async full"/>
</condition>

Is there some possible interplay between timerfd and "send_silence_when_idle" ? We need to always be sending silence when not playing or saying something due to the requirements of upstream carriers.

again, if we remove the application="set" data="timer_name=timerfd" action the problem goes away

To Reproduce
Steps to reproduce the behavior:

1. Use configuration above
2. Dial in and do several successive playback commands
3. Capture pcap and observe strange timestamp jumps at each talkspurt

Expected behavior
We do not expect the timestamp to roll or jump forwards like this outside of an SSRC change or a timestamp value so high that it must roll to zero.

Package version or git hash
git tag v1.10.10

Link to the pcap file mentioned above:
https://drive.google.com/file/d/1jPtGBjNUOURjiD7HCndSZoOFZWvhZP8d/view?usp=sharing

[davehorton]

Just to follow up with some more data and observations on this. The test I have been running is to play 3 short files with a 1 second pause between each. During the pauses silence is generated by freeswitch because I have "send_silence_on_idle" set in my dialplan. As mentioned, I also have timerfd set as the timer.

The issue seems to be that when freeswitch is generating silence due to no file being played, it gets the timestamp from timerfd. When it is playing a file it does not get the timestamp from timerfd. And this seems to lead to a bit of discontinuity at the point where a file ends playing and it shifts from using the timer to not using the timer. And when the file ends playing it shifts back to using the timer again.

I added some logging to make this clearer in my testing.

** generating silence and pulling timestamp from timer

2024-04-16 13:03:12.570254 96.40% [DEBUG] switch_rtp.c:1409 sofia/drachtio_mrf/nobody@10.0.149.54:5070 audio got next ts from timer 12640
2024-04-16 13:03:12.610244 96.40% [DEBUG] switch_rtp.c:1409 sofia/drachtio_mrf/nobody@10.0.149.54:5070 audio got next ts from timer 12800
2024-04-16 13:03:12.610244 96.40% [DEBUG] switch_rtp.c:1409 sofia/drachtio_mrf/nobody@10.0.149.54:5070 audio got next ts from timer 12960

** now playing a file
2024-04-16 13:03:12.610244 96.40% [DEBUG] switch_ivr.c:632 sofia/drachtio_mrf/nobody@10.0.149.54:5070 Command Execute [depth=1] playback(/tmp/tts-2cb7e90a-1730-470c-b3a1-080b44e9333d451f1454-c646-4f12-8358-55db246130de:73df3ccd91dcb327517dfff099f4d5256d41c6ca.mp3)

** timestamp jumps or resets at this point and is no longer pulled from timer

2024-04-16 13:03:12.610244 96.40% [DEBUG] switch_rtp.c:1399 sofia/drachtio_mrf/nobody@10.0.149.54:5070 audio got ts from param 320
2024-04-16 13:03:12.610244 96.40% [DEBUG] switch_rtp.c:1429 sofia/drachtio_mrf/nobody@10.0.149.54:5070 audio setting marker bit
2024-04-16 13:03:12.650220 96.40% [DEBUG] switch_rtp.c:1399 sofia/drachtio_mrf/nobody@10.0.149.54:5070 audio got ts from param 480
2024-04-16 13:03:12.670259 96.40% [DEBUG] switch_rtp.c:1399 sofia/drachtio_mrf/nobody@10.0.149.54:5070 audio got ts from param 640
2024-04-16 13:03:12.690267 96.40% [DEBUG] switch_rtp.c:1399 sofia/drachtio_mrf/nobody@10.0.149.54:5070 audio got ts from param 800

This is down to this part of the code:

freeswitch/src/switch_rtp.c

Line 1548 in 739e770

if (timestamp) {

I'm wondering if there is a reason for not switching the order of that if/else condition such that we use always get the timestamp from the timer, if available?