| Summary: | ASTERISK-28966: chan_pjsip: Interaction with provider re-INVITE and RTP causes codec flip-flop | ||
| Reporter: | Robert Sutton (rsutton@noojee.com.au) | Labels: | fax webrtc |
| Date Opened: | 2020-06-28 20:27:29 | Date Closed: | |
| Priority: | Minor | Regression? | |
| Status: | Open/New | Components: | Channels/chan_pjsip |
| Versions: | 16.10.0 | Frequency of Occurrence | Occasional |
| Related Issues: | |||
| Environment: | ubuntu 18.04, docker, asterisk 16.10 | Attachments: | |
| Description: | we had rtp_symmetric set to "no" on the trunk endpoint
It seems that asterisk and our up stream sip provider got into a feed back loop as can be seen below. This is just a small snippet of this, in 90 seconds this line was logged 600+ times across 3 channels. This was detected because the system was failing to bridge channels, it may not be the cause of failing to bridge, but either way it is a problem. {noformat} Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of ulaw on channel 'PJSIP/trunk-00000f60' when we're sending 'alaw', switching to match Jun 29 10:11:34 chan_pjsip.c:878 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/trunk-00000f60' when we're sending 'ulaw', switching to match {noformat} | ||
| Comments: | By: Asterisk Team (asteriskteam) 2020-06-28 20:27:31.464-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: Robert Sutton (rsutton@noojee.com.au) 2020-06-28 20:29:12.987-0500 BTW, I have a live core dump, and cli output with "debug =1" and "pjsip logger on" available if required. By: Joshua C. Colp (jcolp) 2020-06-29 03:50:48.431-0500 Please attach the debug and further information. The underlying PJSIP configuration would also be needed, and if possible a Wireshark capture. By: Robert Sutton (rsutton@noojee.com.au) 2020-06-30 02:15:08.456-0500 logs and pcap sent to asteriskteam@digium.com endpoint config (realtime) {noformat} 100rel : yes accept_multiple_sdp_answers : false accountcode : acl : deny/permit aggregate_mwi : true allow : (alaw,ulaw) allow_overlap : true allow_subscribe : true allow_transfer : true aors : tmc asymmetric_rtp_codec : false auth : bind_rtp_to_media_address : false bundle : false call_group : callerid : <unknown> callerid_privacy : allowed_not_screened callerid_tag : connected_line_method : invite contact_acl : context : routesv2-inbound cos_audio : 0 cos_video : 0 device_state_busy_at : 10000 direct_media : false direct_media_glare_mitigation : none direct_media_method : invite disable_direct_media_on_nat : false dtls_auto_generate_cert : No dtls_ca_file : dtls_ca_path : dtls_cert_file : dtls_cipher : dtls_fingerprint : SHA-256 dtls_private_key : dtls_rekey : 0 dtls_setup : active dtls_verify : No dtmf_mode : rfc4733 fax_detect : false fax_detect_timeout : 0 follow_early_media_fork : true force_avp : false force_rport : true from_user : g726_non_standard : false ice_support : false identify_by : username,ip ignore_183_without_sdp : false inband_progress : false incoming_mwi_mailbox : language : mailboxes : max_audio_streams : 1 max_video_streams : 1 media_address : media_encryption : no media_encryption_optimistic : false media_use_received_transport : false message_context : moh_passthrough : false moh_suggest : default mwi_from_user : mwi_subscribe_replaces_unsolicited : no named_call_group : named_pickup_group : notify_early_inuse_ringing : false one_touch_recording : false outbound_auth : tmc outbound_proxy : pickup_group : preferred_codec_only : false record_off_feature : automixmon record_on_feature : automixmon refer_blind_progress : true rewrite_contact : false rpid_immediate : false rtcp_mux : false rtp_engine : asterisk rtp_ipv6 : false rtp_keepalive : 0 rtp_symmetric : true rtp_timeout : 0 rtp_timeout_hold : 0 sdp_owner : - sdp_session : Asterisk send_connected_line : yes send_diversion : true send_pai : false send_rpid : false set_var : srtp_tag_32 : false sub_min_expiry : 0 subscribe_context : suppress_q850_reason_headers : false t38_udptl : false t38_udptl_ec : none t38_udptl_ipv6 : false t38_udptl_maxdatagram : 0 t38_udptl_nat : false timers : yes timers_min_se : 90 timers_sess_expires : 1800 tone_zone : tos_audio : 0 tos_video : 0 transport : transport-udp-nat trust_connected_line : yes trust_id_inbound : true trust_id_outbound : true use_avpf : false use_ptime : false user_eq_phone : false voicemail_extension : webrtc : no {noformat} By: Joshua C. Colp (jcolp) 2020-06-30 03:49:43.182-0500 Please do not send logs directly unless asked for and discussed ahead of time. Asterisk is an open source project, and sending to Sangoma limits the interaction on an issue to Sangoma individuals and prevents open source members from seeing/helping/investigating. The sending of information directly should be reserved for extreme cases where sanitization is absolutely not possible. By: Joshua C. Colp (jcolp) 2020-06-30 03:59:22.533-0500 This appears to be due to an interaction between your upstream provider and Asterisk. Unfortunately your pcap does not include RTP traffic so I can not dig into that, but they appear to be re-negotiating to alaw while sending ulaw. We always match what the other side is sending as many devices can't handle otherwise. Upon doing so they attempt to re-negotiate to alaw again, over and over. You could try enabling the asymmetric RTP option, but otherwise new functionality would need to be added to disable the switching behavior. It would have to default to off, and the over all repercussions of it with this provider I'm not sure. By: Joshua C. Colp (jcolp) 2020-06-30 04:01:20.426-0500 If you configure down to a single codec, such as alaw, does that resolve the problem? By: Robert Sutton (rsutton@noojee.com.au) 2020-06-30 23:26:53.522-0500 I would have thought that the problem is probably caused by jitter, lag or just a bad interaction between the 2 systems and that rate limiting the codec change would probably be a suitable solution. Something like 0,250,500,1000 Millis. So upon seeing a different codec it will change immediately and then ignore the codec for 250ms. If after this period another packet with an alternate codec is detected then the codec would change again, and then ignore the codec for a further 500ms. etc. It's really to early to say, won't be sure for a week; but locking the system down to a single codec appears as though it may have solved the problem. However locking the system to a single codec is NOT desirable and fragile. By: Joshua C. Colp (jcolp) 2020-07-01 03:55:59.573-0500 Limiting the codec is for testing the underlying issue to confirm that is the cause. Once past a period of time then my analysis will have been confirmed. I don't know what the ultimate fix will be, as once accepted this would go into the queue and there is no time frame on when it would get looked at or resolved. A community member as well could pick it up and work on it. By: Asterisk Team (asteriskteam) 2020-07-15 12:00:01.734-0500 Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1]. [1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines By: Robert Sutton (rsutton@noojee.com.au) 2020-07-15 18:23:59.463-0500 I can confirm that limiting the codec prevents the flip-flop and may have resolved some call quality issues as well. This did not resolve our call bridging issues, although it now appears that the bridging issues may be caused by an interaction from our AGI. By: Asterisk Team (asteriskteam) 2020-07-15 18:24:00.886-0500 This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable. | ||