<p> Attention is currently required from: Joshua Colp. </p>
<p><a href="https://gerrit.asterisk.org/c/asterisk/+/15985">View Change</a></p><p>1 comment:</p><ul style="list-style: none; padding: 0;"><li style="margin: 0; padding: 0;"><p><a href="null">File apps/app_dial.c:</a></p><ul style="list-style: none; padding: 0;"><li style="margin: 0; padding: 0 0 0 16px;"><p style="margin-bottom: 4px;"><a href="https://gerrit.asterisk.org/c/asterisk/+/15985/comment/15f0b7c2_9a3ae9b9">Patch Set #2, Line 1802:</a> <code style="font-family:monospace,monospace">                                           if (ast_check_hangup_locked(o->chan)) {</code></p><p><blockquote style="border-left: 1px solid #aaa; margin: 10px 0; padding: 0 10px;">I'm not sure what you are referring to. Your statement lacks context. […]</blockquote></p><p style="white-space: pre-wrap; word-wrap: break-word;">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.<br>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.<br>I see some SRCCHANGE frames when the channel is answered (only), but not sure if that is just irrelevant here.<br>Sometimes, I see the prodding failed error in channel.c, sometimes not: https://github.com/asterisk/asterisk/blob/b4347c486150653ec7ce1d129e8f9017c69344da/main/channel.c#L4956<br>Or rather, the error is emitted (it seems) only when there is no wait:<br>[Aug  6 20:36:29] DEBUG[13251][C-00000005]: channel.c:5043 ast_prod: Prodding channel 'Local/bb@recsplit-00000004;1'<br>[Aug  6 20:36:29] WARNING[13251][C-00000005]: channel.c:5048 ast_prod: Prodding channel 'Local/bb@recsplit-00000004;1' failed<br>[Aug  6 20:36:29] DEBUG[13251][C-00000005]: channel.c:5826 set_format: Channel Local/bb@recsplit-00000004;1 setting write format path: ulaw -> ulaw<br>[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<br>[Aug  6 20:36:29] WARNING[13251][C-00000005]: app_dial.c:1807 wait_for_answer: Unable to forward frametype: 2</p><p style="white-space: pre-wrap; word-wrap: break-word;"><br>Here is a scenario with a wait, where the channel isn't prodded during that time (perhaps why there is no error):<br>[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel.c:2465 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'Local/bb@recsplit-00000003;2'<br>[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@recsplit-00000003;2'<br>[Aug  6 20:29:10]   == Spawn extension (recsplit, bb, 5) exited non-zero on 'Local/bb@recsplit-00000003;2'<br>[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel.c:2465 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'Local/bb@recsplit-00000003;2'<br>[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel.c:2556 ast_hangup: Channel 0x7ffb0c011c10 'Local/bb@recsplit-00000003;2' hanging up.  Refs: 2<br>[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel.c:2202 ast_channel_destructor: Channel 0x7ffb0c011c10 'Local/bb@recsplit-00000003;2' destroying<br>[Aug  6 20:29:10] DEBUG[13134]: cdr.c:1470 cdr_object_finalize: Finalized CDR for Local/bb@recsplit-00000003;2 - start 1628281748.909237 answer 0.000000 end 1628281750.058860 dur 1.149 bill 1628281750.058 dispo NO ANSWER<br>[Aug  6 20:29:10] DEBUG[13134]: cdr.c:3523 post_cdr: Skipping CDR for Local/bb@recsplit-00000003;2 since we weren't answered<br>[Aug  6 20:29:10] DEBUG[13214][C-00000004]: channel.c:5826 set_format: Channel Local/bb@recsplit-00000003;1 setting write format path: ulaw -> ulaw<br>[Aug  6 20:29:10] DEBUG[13215][C-00000004]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1628281748.15, detail:<br>[Aug  6 20:29:10] DEBUG[13215][C-00000004]: stasis.c:450 topic_dtor: Topic 'channel:1628281748.15': 0x7ffb0c00ff10 destroyed<br>[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<br>[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel_internal_api.c:682 ast_channel_nativeformats_set:  <initializing>: MultistreamFormats: (nothing)<br>[Aug  6 20:29:10] DEBUG[13215][C-00000004]: channel_internal_api.c:692 ast_channel_nativeformats_set:  Channel is being initialized or destroyed<br>[Aug  6 20:29:10] DEBUG[12971]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for Local - bb@recsplit<br>[Aug  6 20:29:10] DEBUG[12971]: devicestate.c:466 do_state_change: Changing state for Local/bb@recsplit - state 1 (Not in use)<br>[Aug  6 20:29:10] DEBUG[13190]: app_queue.c:2583 device_state_cb: Device 'Local/bb@recsplit' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.<br>[Aug  6 20:29:10] WARNING[13214][C-00000004]: app_dial.c:1807 wait_for_answer: Unable to forward frametype: 2</p><p style="white-space: pre-wrap; word-wrap: break-word;"><br>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".</p><p style="white-space: pre-wrap; word-wrap: break-word;">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?</p></li></ul></li></ul><p>To view, visit <a href="https://gerrit.asterisk.org/c/asterisk/+/15985">change 15985</a>. To unsubscribe, or for help writing mail filters, visit <a href="https://gerrit.asterisk.org/settings">settings</a>.</p><div itemscope itemtype="http://schema.org/EmailMessage"><div itemscope itemprop="action" itemtype="http://schema.org/ViewAction"><link itemprop="url" href="https://gerrit.asterisk.org/c/asterisk/+/15985"/><meta itemprop="name" content="View Change"/></div></div>

<div style="display:none"> Gerrit-Project: asterisk </div>
<div style="display:none"> Gerrit-Branch: master </div>
<div style="display:none"> Gerrit-Change-Id: I6f2ee3f77b892015bc05513d868f071f279a3c80 </div>
<div style="display:none"> Gerrit-Change-Number: 15985 </div>
<div style="display:none"> Gerrit-PatchSet: 2 </div>
<div style="display:none"> Gerrit-Owner: N A <mail@interlinked.x10host.com> </div>
<div style="display:none"> Gerrit-Reviewer: Friendly Automation </div>
<div style="display:none"> Gerrit-Reviewer: Joshua Colp <jcolp@sangoma.com> </div>
<div style="display:none"> Gerrit-Attention: Joshua Colp <jcolp@sangoma.com> </div>
<div style="display:none"> Gerrit-Comment-Date: Fri, 06 Aug 2021 20:41:17 +0000 </div>
<div style="display:none"> Gerrit-HasComments: Yes </div>
<div style="display:none"> Gerrit-Has-Labels: No </div>
<div style="display:none"> Comment-In-Reply-To: Joshua Colp <jcolp@sangoma.com> </div>
<div style="display:none"> Comment-In-Reply-To: N A <mail@interlinked.x10host.com> </div>
<div style="display:none"> Gerrit-MessageType: comment </div>