[Home]

Summary:ASTERISK-28898: bridge_softmix: Conference bridge not passing silent rtp packets
Reporter:Jonathan Hunter (jhunter@voxboxcoms.co.uk)Labels:fax patch
Date Opened:2020-05-15 14:25:50Date Closed:2020-05-20 09:16:08
Priority:MinorRegression?
Status:Closed/CompleteComponents:Bridges/bridge_softmix Channels/chan_sip/General Resources/res_ari_bridges
Versions:16.8.0 16.10.0 Frequency of
Occurrence
Constant
Related
Issues:
Environment:debian 9 Vmware machineAttachments:( 0) ASTERISK-28898.diff
( 1) CoreshowChanneloutputissue.txt
( 2) CoreshowChanneloutputworks.txt
( 3) debug_log_28898issue
( 4) debug_log_28898works
( 5) debug28898issue.pcap
( 6) debug28898works.pcap
( 7) OverviewTopology-OverviewTopology.pdf
Description:Hi Guys,

I raised this issue in the community  and was recommended to open a ticket relating to this.

I have an interesting issue, where when a call is initiated using ARI on
Asterisk 16.8/16/10 , the call connects fine and there is two way audio.

The originator of the call is a sip client, and the called party is a mobile/cell phone.

I wondered if there are any settings I am missing in relation to how ‘silent rtp’ (not comfort noise please see itu spec) is handled as the call uses codec G711A, and when the called party hits the mute button, not all the ‘silent rtp’ packets are passed across channels so after a number of seconds the sip client hears echo (their own breathing and typing on keyboard) and looking at the RTP streams not all the silent rtp packets are passed end to end, it appears some are dropped/not passed by Asterisk, and this only happens when we record the call using /bridges/{bridgeId}/record, if we dont record the silent rtp packets are honoured end to end and we dont have any echo.

This issue I am seeing (and the SSRC remains consistent and there is no packet loss) is that the ‘silent rtp’ (payload all d5) being sent into Asterisk
from the carrier channel, is for example 16 seconds, and initially the channel to the sip client device has this ‘silent rtp’ sent to it, however it is
not for the full duration of time its sent into Asterisk in the carrier channel, it is in some examples 4 seconds but this time can vary (not consistent)
and only happens when we instruct ARI to record the channel for example;

Channel Recorder/ARI-0000001d;2 joined ‘simple_bridge’ stasis-bridge <6122d8f1-9706-4522-8371-539ad1036193>
Bridge 6122d8f1-9706-4522-8371-539ad1036193: switching from simple_bridge technology to softmix

If we dont record the channels this scenario doesnt happen and we get the same duration of ‘silent rtp’ on both the Carrier channel and the sip client channel, so in the example above it would be 16 seconds of silent rtp on both channels as opposed to a shorter duration on the sip client channel.

There are no changes to SSRC, ports etc, the only change is the payload changes from all d5 to what could be considered a normal payload without any obvious changes I can see when running verbose logs

Again this only happens when we record so be great to understand why that is the case.

We can reproduce and provide traces as required in terms of the scenario.

Thanks

Jon
Comments:By: Asterisk Team (asteriskteam) 2020-05-15 14:25:51.899-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].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.

By: Joshua C. Colp (jcolp) 2020-05-15 16:32:17.986-0500

Please attach all available information. Asterisk output, packet traces, everything.

By: Jonathan Hunter (jhunter@voxboxcoms.co.uk) 2020-05-16 06:01:27.975-0500

Hi hope you guys are well,

Please find attached debug logs when I recreated the problem, and also logs where I hangup the recording channel and there is no issue with the silent rtp being sent end to end.
I have also attached a diagram to show high level topology, where we have isolated the issue to what we call TG5 192.168.1.58 and Asterisk 3 192.168.1.99 which is the gateway to our Carrier network and the sip client devices.

In terms of calls, if looking at file debug28898issue.pcap and debug_log_28898issue the inital call initiated from our portal is the nailed up connection to our SIP client extension, in this case 900001;

I have captured all packets on TG5 so you will see the ARI http requests as well as all the SIP/RTP packets, and as this is a test box it is just these calls in question;

In summary;

Time 10:26:35 - SIP Client Channel  Note this is where the issue is seen.
----------------------------------

POST /ARI/channels?endpoint=SIP%2F900001%40loadbalancer&app=CorDiGLA-VD9&timeout=15 HTTP/1.1

Call-ID: 357d5b7b34461aac30a5dffb15ba9ab8@192.168.1.58:5060

Src:192.168.1.58  RTP Port 10486 Dst:192.168.1.99  RTP Port 10024 SSRC:0x7c709481 -RTP leg Where we see Issue of missing
Src:192.168.1.99  RTP Port 10024 Dst:192.168.1.58  RTP Port 10486 SSRC:0x27018279  


Time 10:26:38 - Carrier Channel  This leg out to the carrier
-------------------------------

POST /ARI/channels?endpoint=SIP%2F07917190438%40loadbalancer&app=CorDiGLA-VD9&callerId=01413751174&timeout=31 HTTP/1.1


Call-ID: 76f38a6e10f3bb4c32aefe447f56d35f@192.168.1.58:5060

Src:192.168.1.99 Port 19234  Dst:192.168.1.58 Port 12176     SSRC: 0x38c2cab0  -RTP Leg back from Carrier mobile when I hit mute
Src:192.168.1.58 Port 12176  Dst:Src:192.168.1.99 Port 19234 SSRC: 0x6f25bb13

At this point with the call legs in place when answered we start recording at 10:27:23

POST /ARI/recordings/live/GCMTest2%2FGCM2_Test1%2F20-05-16%2FGCMTest2_GCM2_Test1_BHtest-513652130_20200516102645/stop HTTP/1.1

So as you can see we are looping RTP streams in and out of TG5 back to ASterisk 3 with one channel side going to the SIP client (where we see issue) and the other to the carrier.

So when I hit the mute button on my mobile at 10:26:57 when filtering on payload D5 on SSRC:0x38c2cab0 which is the leg back from the carrier
where I have hit the mutton button, the silent RTP starts at packet 3538(10:26:57)  and stops at packet 8057 (10:27:17) after 20.199 seconds.

Note filter used;

rtp.payload == d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:
d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:
d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:
d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:
d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5:d5 && rtp.ssrc == 0x38c2cab0

Then when I do the same filter on the leg back to the SIP client so SSRC:0x7c709481 if I filter on silent rtp I see the first one at packet 3588 (10:26:57) and the last packet is 6001 (10:27:07) which is after 10.93 seconds.

So at this point the end sip client can then hear themselves type/breath etc as the carrier is sending 20 seconds worth of silent rtp  but in this case only 10 seconds is being passed to the sip client side.

So essentially when recording is in place this happens, and the point at which the silent rtp stops  is not consistent, it can be a mixture of duration's.

If I repeat the test but before hitting mute on the mobile I hang up the recording channel issuing;

channel request hangup Recorder/ARI-0000001d;1 for example and then hit mute the silent rtp packets are honoured as looking in capture debug28898works.pcap;

Time 10:31:43 - SIP Client Channel  Note this is where the issue is seen.
----------------------------------

POST /ARI/channels?endpoint=SIP%2F900001%40loadbalancer&app=CorDiGLA-VD9&timeout=15 HTTP/1.1

Call-ID: 357d5b7b34461aac30a5dffb15ba9ab8@192.168.1.58:5060

Src:192.168.1.58  RTP Port 18792 Dst:192.168.1.99  RTP Port 10662 SSRC: 0x048d1bf4 RTP leg back to SIP client
Src:192.168.1.99  RTP Port 10662 Dst:192.168.1.58  RTP Port 18792 SSRC: 0x3f265e37


Time 10:31:48 - Carrier Channel  This leg out to the carrier
-------------------------------

POST /ARI/channels?endpoint=SIP%2F07917190438%40loadbalancer&app=CorDiGLA-VD9&callerId=01413751174&timeout=31 HTTP/1.1


Call-ID: 76f38a6e10f3bb4c32aefe447f56d35f@192.168.1.58:5060

Src:192.168.1.99 Port 12568  Dst:192.168.1.58 Port 12728     SSRC: 0x6d90dbdf -RTP Leg back from Carrier mobile when I hit mute
Src:192.168.1.58 Port 12728  Dst:Src:192.168.1.99 Port 12568 SSRC: 0x1c170aa2

At this point with the call legs in place and when answered I thne hangup the recorder channels.

I then hit mute  as before and looking at SSRC: 0x6d90dbdf and filtering for silent RTP I see this starts at packet 8243 (10:32:24) and continues
to packet 12950 (10:32:45) for a duration of 21.20 seconds.

If I then look at the rtp leg back to the sip client where we see the issue in the previous example if I filter on SSRC: 0x048d1bf4 and it starts
at packet 8291 (10:32:24) and continues until packet 13000 (10:32:45) for a duration of 21.42 seconds.

And that is the behaviour I would expect, please can you investigate?

If you require anything else please let me know.

Thanks

Jon









By: Joshua C. Colp (jcolp) 2020-05-18 05:17:12.344-0500

For both cases can you please execute "core show channel" on each channel and provide the output.

By: Jonathan Hunter (jhunter@voxboxcoms.co.uk) 2020-05-18 05:59:10.426-0500

Hi hope you are well?

Please find outputs attached (CoreshowChanneloutputissue/works), any issues or not what you require please let me know.

Many thanks

Jon



By: Joshua C. Colp (jcolp) 2020-05-18 06:05:38.132-0500

If you enable "G711_NEW_ALGORITHM" in the "Compiler Flags - Development" portion of "make menuselect" does the result change?

By: Jonathan Hunter (jhunter@voxboxcoms.co.uk) 2020-05-18 09:00:40.988-0500

Hi Joshua,

I recompiled 16.10 with G711_NEW_ALGORITHM so build deps was;

MENUSELECT_BUILD_DEPS=bridge_holding app_cdr func_periodic_hook app_confbridge
res_monitor res_speech res_agi res_stasis res_adsi res_smdi res_odbc
res_crypto res_xmpp res_pjsip res_pjsip_pubsub res_pjsip_session
res_rtp_multicast res_http_websocket res_curl app_chanspy func_cut
func_groupcount func_uri res_ael_share res_ari res_ari_model
res_stasis_recording res_stasis_playback res_stasis_answer
res_stasis_snoop res_stasis_device_state func_curl
res_odbc_transaction res_pjproject res_sorcery_config
res_sorcery_memory res_sorcery_astdb res_statsd
res_pjsip_outbound_publish res_calendar res_fax
res_hep res_phoneprov DONT_OPTIMIZE G711_NEW_ALGORITHM

Which I assume was correct and I reinstalled asterisk with make/make install, I then retested and unfortunately behaviour is still the same.

Jon


By: Joshua C. Colp (jcolp) 2020-05-18 09:44:03.126-0500

Please try the attached patch.

By: Jonathan Hunter (jhunter@voxboxcoms.co.uk) 2020-05-18 13:51:54.771-0500

Hi Joshua,

Thank your for such prompt responses on this and appreciate the patch so quickly.

Initial tests look good and seeing silent rtp end to end and no echo :)  Can I ask do we need the G711_NEW_ALGORITHM enabled as well for this or just need the patch to resolve?

I will just get some colleagues to test as well but looking very good.

Thanks

Jon

By: Joshua C. Colp (jcolp) 2020-05-18 13:55:24.674-0500

Only the patch is needed.

By: Jonathan Hunter (jhunter@voxboxcoms.co.uk) 2020-05-20 03:53:52.603-0500

Hi Joshua,

Apologies for the delay, I was waiting on a remote team to complete testing.

And I am pleased to say the patch fixes the issue perfectly, so thank you so much for your help and prompt response and solution with this issue.

Very much appreciated, please close as you see fit, if you need anything else from me let me know.

Many thanks

Jon

By: Friendly Automation (friendly-automation) 2020-05-20 09:16:10.030-0500

Change 14418 merged by Friendly Automation:
bridge_softmix: Always remove audio from mixed frame.

[https://gerrit.asterisk.org/c/asterisk/+/14418|https://gerrit.asterisk.org/c/asterisk/+/14418]

By: Friendly Automation (friendly-automation) 2020-05-20 09:17:12.991-0500

Change 14417 merged by Friendly Automation:
bridge_softmix: Always remove audio from mixed frame.

[https://gerrit.asterisk.org/c/asterisk/+/14417|https://gerrit.asterisk.org/c/asterisk/+/14417]

By: Friendly Automation (friendly-automation) 2020-05-20 10:00:54.733-0500

Change 14433 merged by Friendly Automation:
bridge_softmix: Always remove audio from mixed frame.

[https://gerrit.asterisk.org/c/asterisk/+/14433|https://gerrit.asterisk.org/c/asterisk/+/14433]

By: Friendly Automation (friendly-automation) 2020-05-20 10:09:25.765-0500

Change 14434 merged by Joshua Colp:
bridge_softmix: Always remove audio from mixed frame.

[https://gerrit.asterisk.org/c/asterisk/+/14434|https://gerrit.asterisk.org/c/asterisk/+/14434]