[asterisk-bugs] [JIRA] (ASTERISK-29428) Failure to send DTMF results in call locking up

Sat May 15 08:03:17 CDT 2021

    [ https://issues.asterisk.org/jira/browse/ASTERISK-29428?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=254901#comment-254901 ] 

N A commented on ASTERISK-29428:
--------------------------------

Yes, this happens with SIP, too, so it appears to be technology-agnostic.

I personally have no clue what could be causing this so I don't think I'd be qualified to work on this.

I played around, and this is all that is necessary to cause this issue:
exten => 123,1,Progress()
	same => n,Hangup()

If you call an extension on your switch *OR* a different switch (doesn't matter), and the Dial() to it has the D progress option set (e.g. Dial(something,,D(::12345))) and you hit something like that, or that effectively does that (progress immediately followed by disconnect), then you can say goodbye to your call. Now it's an endless deluge of:
 WARNING[7009][C-0000085e]: app_dial.c:1798 wait_for_answer: Unable to forward frametype: 2
until you manually hang up the call.

>From what I can tell, there is no way to avoid this issue - obviously, it does not happen if the D(::something) option isn't used, because then the progress doesn't make it want to send DTMF, but I think the problem we have here is that app_dial wants to send DTMF as soon as it gets the Progress, and it doesn't account for scenarios where the channel might have hung up before it could successfully send all the DTMF. As a result, instead of failing with perhaps a single error "Unable to send DTMF", and moving on in the dialplan, it gets stuck in an endless loop of trying to send DTMF that it will never be able to successfully send - because the channel is gone.

Hope that helps! Do you need any more info from me?

> 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: N A
>         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)