Summary:	ASTERISK-25332: marker bit lost in outgoing stream when incoming stream has vad
Reporter:	Gergely Dömsödi (doome)	Labels:
Date Opened:	2015-08-19 13:30:43	Date Closed:
Priority:	Major	Regression?
Status:	Open/New	Components:	Resources/res_rtp_asterisk
Versions:	1.8.32.3 11.18.0 13.3.2 13.4.0	Frequency of Occurrence
Related Issues:
Environment:	Fedora 22	Attachments:	( 0) calls_ast18.pcap ( 1) calls.pcap ( 2) in.pcap ( 3) messages.txt ( 4) out.pcap ( 5) pjsip.conf ( 6) rtp_timestamp_skew_workaround.patch ( 7) rtp_timestamp_skew.patch
Description:	When asterisk receives an incoming call from a peer capable of VAD (rtp packets stop coming on silence, and start coming again on voice), in the outgoing leg of the call, the marker bit is not set on the first packet when the audio is restarted, so the called party is unable to play/sync audio properly.
Comments:	By: Asterisk Team (asteriskteam) 2015-08-19 13:30:45.790-0500 Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report. Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process]. By: Gergely Dömsödi (doome) 2015-08-19 13:33:02.900-0500 Attached the pcap of incoming and outgoing legs of a call which shows the issue. On the incoming stream RTP the marker bit is set properly when the audio is restarted, on the outgoing stream, generated by Asterisk, it is not set. By: Gergely Dömsödi (doome) 2015-08-19 13:36:28.100-0500 The only relevant PJSIP configuration option is that direct_media = no is set on both participating endpoints. By: Rusty Newton (rnewton) 2015-08-20 09:34:24.839-0500 Thanks for the debug so far. Please also attach a debug log[1] that correlates with the pcap (or with a new pcap set) along with the full configuration for the endpoints/peers in question. We need to be able to reproduce the issue typically. Thanks! [1]: https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information By: Gergely Dömsödi (doome) 2015-08-21 07:39:42.199-0500 Attached the debug log, along with a matching pcap (this time the incoming and the outgoing leg is in one pcap) and the corresponding pjsip.conf. With this merged pcap, it can be easily seen for example at 14:05:50.535334, that the incoming stream restarted and the marker bit was set properly, but in the outgoing stream, it was not. By: Gergely Dömsödi (doome) 2015-08-21 07:41:49.596-0500 The same issue was present in older asterisks with chan_sip (tested with 11.18.0), and it is also in 13.4.0 with which this log was made. By: Gergely Dömsödi (doome) 2015-08-24 04:27:20.458-0500 Investigating a bit further, it is interesting that in the second pcap ([^calls.pcap]) I attached, there are times when the marker bit is set after silence, and there are cases when it is not. In {{res_rtp_asterisk.c}} there is a debug line which shows "Difference is..." when timestamp skew is is larger than 640 ms, and if it is 1640ms (at 14:04:54.110099) it is in the logs, and the marker bit is set properly, but when is more, about ~16000ms (at 14:05:52.695958) it is not in the logs, and the marker bit is not set. I also noticed that in the latter case the timestamp is over the 4 byte integer storage (it would fit only in unsigned int) and in {{ast_rtp_raw_write}} the {{pred}} variable used when calculating skew is signed int while {{rtp->lastts}} is unsigned int. I am going to make a patch for this and try if this solves the problem. By: Rusty Newton (rnewton) 2015-08-24 08:44:44.884-0500 Attaching messages.txt and removing messages.call for easy accessibility via browser. By: Gergely Dömsödi (doome) 2015-08-24 09:41:46.445-0500 Unfortunately changing {{pred}} to unsigned int didn't solve the issue (but I still think it should be unsigned, because rtp->lastts is unsigned, too). I inserted some more debug messages there, and it seems that the real problem is that {{ast_tvzero(frame->delivery)}} is false, so the skew check is not reached. Attaching a patch I made for debugging and the debug output when {{ast_rtp_raw_write()}} should set the marker bit, but it did not. The debug output: {noformat} [2015-08-24 15:20:32.405624] DEBUG[11560][C-00000a66] audiohook.c: Write factory 0x7fe5611af068 was pretty quick last time, waiting for them. [2015-08-24 15:20:32.405654] DEBUG[11636][C-00000a66] res_rtp_asterisk.c: lassts: 1935205808, ms: 1700, diff: 13440, rate: 8, pred: 1935192368 [2015-08-24 15:20:32.405665] DEBUG[11636][C-00000a66] res_rtp_asterisk.c: ast_tvzero(frame->delivery) is false {noformat} By: Gergely Dömsödi (doome) 2015-08-24 09:42:40.862-0500 The patch I used to debug the issue. By: Gergely Dömsödi (doome) 2015-08-25 03:21:39.599-0500 I made a little [patch|^rtp_timestamp_skew_workaround.patch] to workaround to problem. It is not supposed to be production-ready (I lack detailed knowledge of the RTP stack to do that), but it seems to solve the issue for me. When applied, the marker bit is set every time in the outgoing stream when there is pause in the incoming audio. Note that the signed-unsigned modification which was part of the debug patch is not used in this one. By: Gergely Dömsödi (doome) 2015-08-26 05:16:42.739-0500 I made a [pcap|^calls_ast18.pcap] on asterisk 1.8.32.3 too, and it is also affected, but slightly differently. In the attached pcap it can be seen for example at 10:53:53.560032, that the audio in the incoming stream restarts, it comes with delayed timestamp and the marker bit set, but this asterisk sends it out as it was just the next packet of the audio stream: without the marker bit set, and with the timestamp incremented only with 160, as it was the direct following of the packet which was sent seconds before. In Asterisk 13, the timestamps were incremented properly. Unfortunately, I am not able to make a proper debug log on this system, becase it is a production one.