[Asterisk-code-review] app_dial: Prevent call from hanging (asterisk[master])

[N A]

Attention is currently required from: Joshua Colp.
N A has posted comments on this change. ( https://gerrit.asterisk.org/c/asterisk/+/15985 )

Change subject: app_dial: Prevent call from hanging
......................................................................


Patch Set 2:

(1 comment)

File apps/app_dial.c:

https://gerrit.asterisk.org/c/asterisk/+/15985/comment/15f0b7c2_9a3ae9b9 
PS2, Line 1802: 						if (ast_check_hangup_locked(o->chan)) {
> I'm not sure what you are referring to. Your statement lacks context. […]
This issue appears to happen with MF as well, and it ends up in the same place, even though DTMF frames aren't being sent. If I Progress, ReceiveMF, then wait 0.3 seconds, that's long enough to prevent the issue from happening. Waiting only 0.05 seconds isn't, and we get stuck in the infinite loop.
What is the actual "normal" mechanism in app_dial that is supposed to detect hangups? I added some debugs and the AST_CONTROL_HANGUP branch doesn't execute either way. There seems to be a small window of time where bad things can happen.
I see some SRCCHANGE frames when the channel is answered (only), but not sure if that is just irrelevant here.
Sometimes, I see the prodding failed error in channel.c, sometimes not: https://github.com/asterisk/asterisk/blob/b4347c486150653ec7ce1d129e8f9017c69344da/main/channel.c#L4956
Or rather, the error is emitted (it seems) only when there is no wait:
[Aug  6 20:36:29] DEBUG[13251][C-00000005]: channel.c:5043 ast_prod: Prodding channel 'Local/bb at recsplit-00000004;1'
[Aug  6 20:36:29] WARNING[13251][C-00000005]: channel.c:5048 ast_prod: Prodding channel 'Local/bb at recsplit-00000004;1' failed
[Aug  6 20:36:29] DEBUG[13251][C-00000005]: channel.c:5826 set_format: Channel Local/bb at recsplit-00000004;1 setting write format path: ulaw -> ulaw
[Aug  6 20:36:29] DEBUG[13251][C-00000005]: channel.c:3215 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug  6 20:36:29] WARNING[13251][C-00000005]: app_dial.c:1807 wait_for_answer: Unable to forward frametype: 2


Here is a scenario with a wait, where the channel isn't prodded during that time (perhaps why there is no error):
[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel.c:2465 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'Local/bb at recsplit-00000003;2'
[Aug  6 20:29:10] DEBUG[13215][C-00000004]: pbx.c:4441 __ast_pbx_run: Spawn extension (recsplit,bb,5) exited non-zero on 'Local/bb at recsplit-00000003;2'
[Aug  6 20:29:10]   == Spawn extension (recsplit, bb, 5) exited non-zero on 'Local/bb at recsplit-00000003;2'
[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel.c:2465 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'Local/bb at recsplit-00000003;2'
[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel.c:2556 ast_hangup: Channel 0x7ffb0c011c10 'Local/bb at recsplit-00000003;2' hanging up.  Refs: 2
[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel.c:2202 ast_channel_destructor: Channel 0x7ffb0c011c10 'Local/bb at recsplit-00000003;2' destroying
[Aug  6 20:29:10] DEBUG[13134]: cdr.c:1470 cdr_object_finalize: Finalized CDR for Local/bb at recsplit-00000003;2 - start 1628281748.909237 answer 0.000000 end 1628281750.058860 dur 1.149 bill 1628281750.058 dispo NO ANSWER
[Aug  6 20:29:10] DEBUG[13134]: cdr.c:3523 post_cdr: Skipping CDR for Local/bb at recsplit-00000003;2 since we weren't answered
[Aug  6 20:29:10] DEBUG[13214][C-00000004]: channel.c:5826 set_format: Channel Local/bb at recsplit-00000003;1 setting write format path: ulaw -> ulaw
[Aug  6 20:29:10] DEBUG[13215][C-00000004]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1628281748.15, detail:
[Aug  6 20:29:10] DEBUG[13215][C-00000004]: stasis.c:450 topic_dtor: Topic 'channel:1628281748.15': 0x7ffb0c00ff10 destroyed
[Aug  6 20:29:10] DEBUG[13214][C-00000004]: channel.c:3215 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel_internal_api.c:682 ast_channel_nativeformats_set:  <initializing>: MultistreamFormats: (nothing)
[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel_internal_api.c:692 ast_channel_nativeformats_set:  Channel is being initialized or destroyed
[Aug  6 20:29:10] DEBUG[12971]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for Local - bb at recsplit
[Aug  6 20:29:10] DEBUG[12971]: devicestate.c:466 do_state_change: Changing state for Local/bb at recsplit - state 1 (Not in use)
[Aug  6 20:29:10] DEBUG[13190]: app_queue.c:2583 device_state_cb: Device 'Local/bb at recsplit' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Aug  6 20:29:10] WARNING[13214][C-00000004]: app_dial.c:1807 wait_for_answer: Unable to forward frametype: 2


Prodding only occurs before a channel is answered, so it seems like there is a small window of time where channels are in an inconsistent state, where if hung up, that will just "leak through".

I do wonder if the prodding error here is a sign of whatever it is causing this not working properly. Is it expected that prodding a channel would fail on a hangup, or should the channel already be gone by the time it checks again? Maybe the progress tones are preventing app_dial from doing what it needs to do in order to process frames received during that time or immediately thereafter?



-- 
To view, visit https://gerrit.asterisk.org/c/asterisk/+/15985
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings

Gerrit-Project: asterisk
Gerrit-Branch: master
Gerrit-Change-Id: I6f2ee3f77b892015bc05513d868f071f279a3c80
Gerrit-Change-Number: 15985
Gerrit-PatchSet: 2
Gerrit-Owner: N A <mail at interlinked.x10host.com>
Gerrit-Reviewer: Friendly Automation
Gerrit-Reviewer: Joshua Colp <jcolp at sangoma.com>
Gerrit-Attention: Joshua Colp <jcolp at sangoma.com>
Gerrit-Comment-Date: Fri, 06 Aug 2021 20:41:17 +0000
Gerrit-HasComments: Yes
Gerrit-Has-Labels: No
Comment-In-Reply-To: Joshua Colp <jcolp at sangoma.com>
Comment-In-Reply-To: N A <mail at interlinked.x10host.com>
Gerrit-MessageType: comment
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-code-review/attachments/20210806/02684258/attachment-0001.html>