[asterisk-bugs] [JIRA] (ASTERISK-29780) bridge: IAX2 call where side A splits call on answer and side B sends DTMF on answer to called party on DAHDI line can cause bidirectional audio to drop permanently due to AST_CONTROL_SRCCHANGE
N A (JIRA)
noreply at issues.asterisk.org
Sat Dec 4 20:30:34 CST 2021
[ https://issues.asterisk.org/jira/browse/ASTERISK-29780?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
N A updated ASTERISK-29780:
---------------------------
Attachment: min_example_side_a.txt
Looks like the formatting got messed up on that comment... here it is as a txt.
This is the minimally reproducible dialplan for this bug on the originating side.
> bridge: IAX2 call where side A splits call on answer and side B sends DTMF on answer to called party on DAHDI line can cause bidirectional audio to drop permanently due to AST_CONTROL_SRCCHANGE
> -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: ASTERISK-29780
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-29780
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Channels/chan_iax2, Core/Bridging, Core/Channels
> Affects Versions: 18.8.0
> Reporter: N A
> Assignee: Unassigned
> Attachments: A to B directly (fail).txt, A to B directly with just console channel driver (success).txt, A to C to B (fail).txt, A to C to B, log from C (fail).txt, Issue.txt, min_example_side_a.txt
>
>
> We have discovered that if a call is made over IAX2 into an Asterisk system that completes the call using DAHDI, if the D() option is used on the DAHDI side to send any DTMF tones to the called party on answer, that will cause audio to stop passing for the remainder of the call. This appears to be a complex interaction of factors between the two sides of the call. Several conditions must be just right, and if so the call will fail every single time.
> - Call must complete using DAHDI to the destination line on Side B. No issues with SIP.
> - The D option must be used in Dial on Side B to send DTMF digits to the destination endpoint on answer. Digits do not matter. No issues if no DTMF sent.
> - Only IAX2 between A and B has been tested. Trunk is not encrypted or authenticated.
> - Side A must use the G option for Dial to split the call on answer. No issues if call is not split.
> If A originates a call to B in the Asterisk CLI using the console channel driver, there are no audio issues.
> If using an ATA registered to A to make a call through B, where the first thing that Asterisk A does is call B, there are no audio issues.
> If the call on side A is set up in just the right particular way, then the no audio issue can occur. This will occur regardless of whether A ends up calling B directly or the call goes through an intermediary (say, C), which then directly calls B.
> The exact mechanism of this bug appears to be that DAHDI on Side B will send a control frame over IAX2 to the originating side. On a good call, that is all that happens. However, on a bad call, this control frame is "echoed" back to Side B, and this causes audio to drop in both directions for the remainder of the call.
> Side A tested with several versions of Asterisk 18. Side B is running Asterisk 11. The issue itself is on Side A, however. It is merely an issue that is made obvious in response to a control frame being sent from Side B. This therefore appears to a bug with core bridging and/or IAX2.
> Using iax2 debug / debug 10, I have narrowed down the exact point where the issue starts to this:
> [2021-11-28 14:35:46] DEBUG[26626][C-000000c9]: chan_iax2.c:5762 iax2_indicate: Indicating condition -1 <---------------------------- NOT NORMAL.
> [2021-11-28 14:35:46] DEBUG[26625][C-000000c9]: pbx.c:2938 pbx_extension_helper: Launching 'Set'
> [2021-11-28 14:35:46] DEBUG[1268]: chan_iax2.c:3414 send_packet: Sending 7823 on 12206/6856 to ASTERISK-SIDE-B-IP
> [2021-11-28 14:35:46] Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 004 Type: CONTROL Subclass: (255?) <---------------------------- transmit 255? back to side B. NOT NORMAL.
> [2021-11-28 14:35:46] Timestamp: 07823ms SCall: 12206 DCall: 06856 ASTERISK-SIDE-B-IP
> This always starts directly after the "Indicating condition -1", which does NOT show up on a good call, only on bad calls.
> This does, furthermore, appear to be linked to a CONTROL frame of 255?. Usually, Side B sends one of these to Side A. It seems that on bad calls, this CONTROL frame of 255? is echoed back to Side B. Additionally, I see "Blocked sending condition 26" which does not appear in a good call.
> Condition 26 appears to be AST_CONTROL_SRCCHANGE = 26, /*!< Media source has changed and requires a new RTP SSRC */. -1 isn't a condition, so I'm assuming that means some failure has occured which may be why this is happening.
> [Nov 28 09:43:28] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER
> [Nov 28 09:43:28] Timestamp: 07774ms SCall: 13234 DCall: 12944 ASTERISK-SIDE-B-IP
> [Nov 28 09:43:28] DEBUG[18882][C-00000354]: chan_iax2.c:10404 socket_process_helper: Received packet 2, (4, 4)
> [Nov 28 09:43:28] DEBUG[18882][C-00000354]: chan_iax2.c:3414 send_packet: Sending 7774 on 12944/13234 to ASTERISK-SIDE-B-IP
> [Nov 28 09:43:28] Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK
> [Nov 28 09:43:28] Timestamp: 07774ms SCall: 12944 DCall: 13234 ASTERISK-SIDE-B-IP
> [Nov 28 09:43:28] DEBUG[18882][C-00000354]: chan_iax2.c:11996 socket_process_helper: For call=12944, set last=7774
> [Nov 28 09:43:28] Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?) <----------------------------------- we get a 255? from Side B. This is normal.
> [Nov 28 09:43:28] Timestamp: 07777ms SCall: 13234 DCall: 12944 ASTERISK-SIDE-B-IP
> [Nov 28 09:43:28] DEBUG[18882][C-00000354]: chan_iax2.c:10404 socket_process_helper: Received packet 3, (4, -1)
> [Nov 28 09:43:28] DEBUG[18882][C-00000354]: chan_iax2.c:3414 send_packet: Sending 7777 on 12944/13234 to ASTERISK-SIDE-B-IP
> [Nov 28 09:43:28] Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 004 Type: IAX Subclass: ACK
> [Nov 28 09:43:28] Timestamp: 07777ms SCall: 12944 DCall: 13234 ASTERISK-SIDE-B-IP
> .....
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: chan_iax2.c:5743 iax2_indicate: Indicating condition 26 <---------------------- NOT NORMAL.
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: chan_iax2.c:7745 send_command: Callno 11602: Blocked sending control frame 26. <---------------------- NOT NORMAL.
> [Nov 28 09:43:28] DEBUG[18870]: cdr.c:1470 cdr_object_finalize: Finalized CDR for IAX2/ASTERISK-SIDE-B-IP:4569-12944 - start 1638110600.454928 answer 1638110608.228645 end 1638110608.232358 dur 7.777 bill 0.003 dispo ANSWERED
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: chan_iax2.c:5743 iax2_indicate: Indicating condition 26 <---------------------- NOT NORMAL.
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: chan_iax2.c:7745 send_command: Callno 12944: Blocked sending control frame 26. <---------------------- NOT NORMAL.
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: chan_iax2.c:5743 iax2_indicate: Indicating condition -1 <----------------------------- NOT NORMAL.
> [Nov 28 09:43:28] TE-Frame Retry[000] -- OSeqno: 007 ISeqno: 009 Type: CONTROL Subclass: (255?) <---------------------------- We forward the 255? to originating switch.
> [Nov 28 09:43:28] Timestamp: 09821ms SCall: 11602 DCall: 17130 ASTERISK-SIDE-A-IP
> For reference, this is what happens immediately prior to the indicating condition 26. This is a call from A -> C -> B (debug from C):
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: bridge_channel.c:2911 bridge_channel_internal_join: Bridge d13d477a-3765-433c-8f13-7f57369fdd64: 0x7fa8d407dba0(IAX2/ASTERISK-SIDE-B-IP:4569-12944) is joining
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: bridge_channel.c:2251 bridge_channel_internal_push_full: Bridge d13d477a-3765-433c-8f13-7f57369fdd64: pushing 0x7fa8d407dba0(IAX2/ASTERISK-SIDE-B-IP:4569-12944)
> [Nov 28 09:43:28] -- Channel IAX2/ASTERISK-SIDE-B-IP:4569-12944 joined 'simple_bridge' basic-bridge <d13d477a-3765-433c-8f13-7f57369fdd64>
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: stasis_bridges.c:290 bridge_snapshot_update_create: Update: 0x7fa8b401db98 Old: d13d477a-3765-433c-8f13-7f57369fdd64 New: d13d477a-3765-433c-8f13-7f57369fdd64
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: stasis_bridges.c:270 bridge_snapshot_update_dtor: Update: 0x7fa8b401db98 Old: d13d477a-3765-433c-8f13-7f57369fdd64 New: d13d477a-3765-433c-8f13-7f57369fdd64
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: bridge_native_rtp.c:774 native_rtp_bridge_compatible: Bridge 'd13d477a-3765-433c-8f13-7f57369fdd64' can not use native RTP bridge as two channels are required
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: bridge.c:535 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: bridge.c:525 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: bridge.c:525 find_best_technology: Bridge technology softmix does not have any capabilities we want.
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: bridge.c:549 find_best_technology: Chose bridge technology simple_bridge
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: bridge.c:1058 smart_bridge_operation: Bridge d13d477a-3765-433c-8f13-7f57369fdd64 is already using the new technology.
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: bridge.c:448 bridge_channel_complete_join: Bridge d13d477a-3765-433c-8f13-7f57369fdd64: 0x7fa8d407dba0(IAX2/ASTERISK-SIDE-B-IP:4569-12944) is joining simple_bridge technology
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: stasis_bridges.c:290 bridge_snapshot_update_create: Update: 0x7fa8b4019e88 Old: d13d477a-3765-433c-8f13-7f57369fdd64 New: d13d477a-3765-433c-8f13-7f57369fdd64
> [Nov 28 09:43:28] DEBUG[76886][C-00000354]: stasis_bridges.c:270 bridge_snapshot_update_dtor: Update: 0x7fa8b4019e88 Old: d13d477a-3765-433c-8f13-7f57369fdd64 New: d13d477a-3765-433c-8f13-7f57369fdd64
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge_channel.c:2911 bridge_channel_internal_join: Bridge d13d477a-3765-433c-8f13-7f57369fdd64: 0x7fa8d411a650(IAX2/sfcu-11602) is joining
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge_channel.c:2251 bridge_channel_internal_push_full: Bridge d13d477a-3765-433c-8f13-7f57369fdd64: pushing 0x7fa8d411a650(IAX2/sfcu-11602)
> [Nov 28 09:43:28] -- Channel IAX2/sfcu-11602 joined 'simple_bridge' basic-bridge <d13d477a-3765-433c-8f13-7f57369fdd64>
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: stasis_bridges.c:290 bridge_snapshot_update_create: Update: 0x7fa8d405bf88 Old: d13d477a-3765-433c-8f13-7f57369fdd64 New: d13d477a-3765-433c-8f13-7f57369fdd64
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: stasis_bridges.c:270 bridge_snapshot_update_dtor: Update: 0x7fa8d405bf88 Old: d13d477a-3765-433c-8f13-7f57369fdd64 New: d13d477a-3765-433c-8f13-7f57369fdd64
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge_native_rtp.c:647 native_rtp_bridge_compatible_check: Bridge 'd13d477a-3765-433c-8f13-7f57369fdd64'. Checking compatability for channels 'IAX2/ASTERISK-SIDE-B-IP:4569-12944' and 'IAX2/sfcu-11602'
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge_native_rtp.c:657 native_rtp_bridge_compatible_check: Bridge 'd13d477a-3765-433c-8f13-7f57369fdd64' can not use native RTP bridge as channel 'IAX2/sfcu-11602' has features which prevent it
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge.c:535 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge.c:525 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge.c:525 find_best_technology: Bridge technology softmix does not have any capabilities we want.
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge.c:549 find_best_technology: Chose bridge technology simple_bridge
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge.c:1058 smart_bridge_operation: Bridge d13d477a-3765-433c-8f13-7f57369fdd64 is already using the new technology.
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: bridge.c:448 bridge_channel_complete_join: Bridge d13d477a-3765-433c-8f13-7f57369fdd64: 0x7fa8d411a650(IAX2/sfcu-11602) is joining simple_bridge technology
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: channel.c:5752 set_format: Channel IAX2/sfcu-11602 setting read format path: ulaw -> ulaw
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: channel.c:5752 set_format: Channel IAX2/ASTERISK-SIDE-B-IP:4569-12944 setting write format path: ulaw -> ulaw
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: channel.c:5752 set_format: Channel IAX2/ASTERISK-SIDE-B-IP:4569-12944 setting read format path: ulaw -> ulaw
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: channel.c:5752 set_format: Channel IAX2/sfcu-11602 setting write format path: ulaw -> ulaw
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: stasis_bridges.c:290 bridge_snapshot_update_create: Update: 0x7fa8d4024cb8 Old: d13d477a-3765-433c-8f13-7f57369fdd64 New: d13d477a-3765-433c-8f13-7f57369fdd64
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: stasis_bridges.c:270 bridge_snapshot_update_dtor: Update: 0x7fa8d4024cb8 Old: d13d477a-3765-433c-8f13-7f57369fdd64 New: d13d477a-3765-433c-8f13-7f57369fdd64
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: chan_iax2.c:5743 iax2_indicate: Indicating condition 26 <---------------------- NOT NORMAL.
> [Nov 28 09:43:28] DEBUG[76877][C-00000354]: chan_iax2.c:7745 send_command: Callno 11602: Blocked sending control frame 26. <---------------------- NOT NORMAL.
> [Nov 28 09:43:28] DEBUG[18870]: cdr.c:1470 cdr_object_finalize: Finalized CDR for IAX2/ASTERISK-SIDE-B-IP:4569-12944 - start 1638110600.454928 answer 1638110608.228645 end 1638110608.232358 dur 7.777 bill 0.003 dispo ANSWERED
> .....
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list