[asterisk-bugs] [JIRA] (ASTERISK-29428) Failure to send DTMF results in call locking up
N A (JIRA)
noreply at issues.asterisk.org
Thu May 13 21:13:17 CDT 2021
[ https://issues.asterisk.org/jira/browse/ASTERISK-29428?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=254890#comment-254890 ]
N A edited comment on ASTERISK-29428 at 5/13/21 9:12 PM:
---------------------------------------------------------
I did some further testing on this today and here is what I noticed:
If I *remove* the Progress() on the remote end and replace it with a NoOp(), execution is as expected. There aren't any warnings, and dialplan execution continues immediately.
The below will cause the above issues with the infinite barage of warning spam and frozen dialplan execution:
[May 13 22:03:11] -- Executing [REDACTED at users:1] Progress("IAX2/REDACTED:4569-8334", "") in new stack
[May 13 22:03:11] -- Executing [REDACTED at users:2] SIPAddHeader("IAX2/REDACTED:4569-8334", "Request-Line:7") in new stack
[May 13 22:03:11] -- Executing [REDACTED at users:3] Dial("IAX2/REDACTED:4569-8334", "SIP/91,10") in new stack
[May 13 22:03:11] WARNING[32382][C-00000843]: app_dial.c:2527 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent)
[May 13 22:03:11] == Everyone is busy/congested at this time (1:0/0/1)
[May 13 22:03:11] -- Executing [REDACTED at users:4] Hangup("IAX2/REDACTED:4569-8334", "") in new stack
This, however, will not:
[May 13 22:06:12] -- Executing [REDACTED at users:1] NoOp("IAX2/REDACTED:4569-1345", "") in new stack
[May 13 22:06:12] -- Executing [REDACTED at users:2] SIPAddHeader("IAX2/REDACTED:4569-1345", "Request-Line:7") in new stack
[May 13 22:06:12] -- Executing [REDACTED at users:3] Dial("IAX2/REDACTED:4569-1345", "SIP/91,10") in new stack
[May 13 22:06:12] WARNING[32470][C-00000844]: app_dial.c:2527 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent)
[May 13 22:06:12] == Everyone is busy/congested at this time (1:0/0/1)
[May 13 22:06:12] -- Executing [REDACTED at users:4] Hangup("IAX2/REDACTED:4569-1345", "") in new stack
It thus appears that if you have two Asterisk nodes, Nodes A and Node B, and Node A initiates a call to Node B which provides Progress() but immediately hangs up because it's unable to do what it wanted to do, this can cause serious issues with the call on Node A's side, since Node A now will want to send the DTMF on Progress, but the call is toast by the time it's doing that.
was (Author: interlinked):
I did some further testing on this today and here is what I noticed:
If I *remove* the Progress() on the remote end and replace it with a NoOp(), execution is as expected. There aren't any warnings, and dialplan execution continues immediately.
The below will cause the above issues with the infinite barage of warning spam and frozen dialplan execution:
[May 13 22:03:11] -- Executing [REDACTED at users:1] Progress("IAX2/REDACTED:4569-8334", "") in new stack
[May 13 22:03:11] -- Executing [REDACTED at users:2] SIPAddHeader("IAX2/REDACTED:4569-8334", "Request-Line:7") in new stack
[May 13 22:03:11] -- Executing [REDACTED at users:3] Dial("IAX2/REDACTED:4569-8334", "SIP/91,10") in new stack
[May 13 22:03:11] WARNING[32382][C-00000843]: app_dial.c:2527 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent)
[May 13 22:03:11] == Everyone is busy/congested at this time (1:0/0/1)
[May 13 22:03:11] -- Executing [REDACTED at users:4] Hangup("IAX2/REDACTED:4569-8334", "") in new stack
This, however, will not:
[May 13 22:06:12] -- Executing [REDACTED at users:1] NoOp("IAX2/REDACTED:4569-1345", "") in new stack
[May 13 22:06:12] -- Executing [REDACTED at users:2] SIPAddHeader("IAX2/REDACTED:4569-1345", "Request-Line:7") in new stack
[May 13 22:06:12] -- Executing [REDACTED at users:3] Dial("IAX2/REDACTED:4569-1345", "SIP/91,10") in new stack
[May 13 22:06:12] WARNING[32470][C-00000844]: app_dial.c:2527 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent)
[May 13 22:06:12] == Everyone is busy/congested at this time (1:0/0/1)
[May 13 22:06:12] -- Executing [REDACTED at users:4] Hangup("IAX2/REDACTED:4569-1345", "") in new stack
It thus appears that if you have two Asterisk nodes, Nodes A and Node B, and Node A initiates a call to Node B which provides Progress() but immediately hangs up because it's unable to do what it wanted to do, this can cause serious issues with the call on Node A's side.
> Failure to send DTMF results in call locking up
> -----------------------------------------------
>
> Key: ASTERISK-29428
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-29428
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Applications/app_dial
> Affects Versions: 18.3.0
> Environment: Debian 10
> Reporter: N A
> Assignee: Unassigned
> Attachments: debug.txt
>
>
> I've been trying to troubleshoot a weird issue I can reproduce consistently, which results in thousands of these spamming the console:
> ```
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> ```
> The frame type in question is an AST_FRAME_DTMF_END frame. I tested a few different ways, and what's happening is I'm trying to call a remote FXO line that appears to be down currently (HANGUPCAUSE = 20). Calling it directly, I just hear a reorder tone (since that's how it gets handled that particular way). In a different place, I have the D option configured to send DTMF on Progress, and the CLI confirms that's what it's trying to do:
> ```
> [May 12 22:02:42] -- Channel Local/SIPATAxLA1 at centrex-outgoing-00001d85;2 joined 'softmix' base-bridge <9f5d2e80-cdf9-433f-b84d-2494409ea318>
> [May 12 22:02:42] -- Local/SIPATAxLA1 at centrex-outgoing-00001d85;1 requested media update control 20, passing it to Local/REDACTED at centrex-originate-local-00001d87;1
> [May 12 22:02:42] -- Local/REDACTED at centrex-originate-local-00001d87;2 requested media update control 20, passing it to Local/FX1A1DC824 at centrex-fx-00001d88;1
> [May 12 22:02:42] -- Local/FX1A1DC824 at centrex-fx-00001d88;2 requested media update control 20, passing it to IAX2/REDACTED:4569-13337
> [May 12 22:02:42] -- Local/SIPATAxLA1 at centrex-outgoing-00001d85;1 requested media update control 20, passing it to Local/REDACTED at centrex-originate-local-00001d87;1
> [May 12 22:02:42] -- Local/REDACTED at centrex-originate-local-00001d87;2 requested media update control 20, passing it to Local/FX1A1DC824 at centrex-fx-00001d88;1
> [May 12 22:02:42] -- Local/FX1A1DC824 at centrex-fx-00001d88;2 requested media update control 20, passing it to IAX2/REDACTED:4569-13337
> [May 12 22:02:44] -- IAX2/REDACTED:4569-13337 is making progress passing it to Local/FX1A1DC824 at centrex-fx-00001d88;2
> [May 12 22:02:44] -- Local/FX1A1DC824 at centrex-fx-00001d88;1 is making progress passing it to Local/REDACTED at centrex-originate-local-00001d87;2
> [May 12 22:02:44] -- Sending DTMF 'REDACTED' to the called party as result of receiving a PROGRESS message.
> [May 12 22:02:44] -- Local/REDACTED at centrex-originate-local-00001d87;1 is making progress passing it to Local/SIPATAxLA1 at centrex-outgoing-00001d85;1
> [May 12 22:02:44] -- Hungup 'IAX2/redacted:4569-13337'
> [May 12 22:02:44] == Everyone is busy/congested at this time (1:0/0/1)
> [May 12 22:02:44] -- Executing [s at REDACTED-simple:4] Return("Local/FX1A1DC824 at centrex-fx-00001d88;2", "20") in new stack
> [May 12 22:02:44] -- Executing [FX1A1DC824 at centrex-fx:2] Hangup("Local/FX1A1DC824 at centrex-fx-00001d88;2", "20") in new stack
> [May 12 22:02:44] == Spawn extension (centrex-fx, FX1A1DC824, 2) exited non-zero on 'Local/FX1A1DC824 at centrex-fx-00001d88;2'
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> [2021-05-12 22:02:44] WARNING[1817][C-00001ec9]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
> ```
> That goes on forever, hundreds of times per second, until I manually hang up the call. All the while, I don't hear anything in the call itself and dialplan execution doesn't continue until I hang up. There seems to be some kind of bug here with not accounting for something here but I can't quite put my finger on it... however, this does happen every single time. It's not able to send the DTMF, but this basically locks up the call afterwards for perpetuity because of that.
> It's worth mentioning the end call that is being made (via IAX2), is to another Asterisk machine over the Internet. That is to say, not my dialplan. The FXO gateway is connected to that Asterisk switch. It's possible that switch is introducing a Progress() it shouldn't be that's causing this to happen, but it seems Asterisk should be able to handle that.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list