<div dir="ltr"><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">Someone complained about errant behavior of the Busy and Hangup apps...<br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">and I see some strangenesses that might make them credible.<br><br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">Boy, did I have to chase this around to find what I think is the problem!<br><br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">What happens: The (eg) Busy app is called. Instead of it waiting a generous 15 seconds,<br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">it immediately hangs up, not forwarding anything to the trunk the call came in from. This<br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">is the closing act in the blocking of a call, executed from the dialplan.<br><br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">With a generous amount of debug added to help explain the order of execution, I see<br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">this:<br><br>[02-Apr-2018 23:31:25.313] VERBOSE[21813][C-00000005] pbx.c: Executing [s@Busy:1] Busy("SIP/sip-out-5-00000002", "15") in new stack<br>[02-Apr-2018 23:31:25.313] VERBOSE[21813][C-00000005] pbx.c: in pbx_builtin_busy, about to indicate, data is 15<br>[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: returned from ast_indicate<br>[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: got lock<br>[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: channel not up, setting hangup cause<br>[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: setting channel to busy<br>[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: unlocked, waiting for handup<br>[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: in wait_for_hangup, data is 15<br>[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: wait_for_hangup, waitsec is: 15<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] pbx.c: wait_for_hangup, waittime is: 15000<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep() calling ast_safe_sleep_conditional()<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: entered, timeout_ms: 15000<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: in while(); <br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: made it past the cond test, about to call waitfor; <br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: ast_waitfor calling ast_waitfor_nandfds()<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds();n=1, nfds=0<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); past the first for() statement-- wait full interval<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); build the pollfd array. rms=15000, AST_MAX_FDS=11<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); Add the individual fds nfds=0<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); start= 67108865<br>[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); Linux fix <br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); ast_poll returns 1; max=4, kbrms=15000<br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: pfds[0].fd = 25; .events=3; .revents=0<br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: pfds[1].fd = 26; .events=3; .revents=0<br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: pfds[2].fd = 30; .events=3; .revents=0<br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: pfds[3].fd = 31; .events=3; .revents=1<br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); cleared flags rms=15000, res=1<br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); check for pending events max=4<br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); past the pending events for loop, ms=15000<br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); Final return of winner<br>[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: made it past the cond test, waitfor returns 15000 <br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: made it past ast_waitfor, ms>0<br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: ast_read returned<br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: <span style="background-color:rgb(255,0,0)">ast_safe_sleep_conditional: ast_read returned a frame</span><br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: the frame is NOT deferrable<br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: in while(); <br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: made it past the cond test, about to call waitfor; <br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: ast_waitfor calling ast_waitfor_nandfds()<br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds();n=1, nfds=0<br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); past the first for() statement-- wait full interval<br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); build the pollfd array. rms=14998, AST_MAX_FDS=11<br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); Add the individual fds nfds=0<br>[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); start= 67108865<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); Linux fix <br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); ast_poll returns 1; max=4, kbrms=14998<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: pfds[0].fd = 25; .events=3; .revents=0<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: pfds[1].fd = 26; .events=3; .revents=0<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: pfds[2].fd = 30; .events=3; .revents=0<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: pfds[3].fd = 31; .events=3; .revents=1<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); cleared flags rms=14998, res=1<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); check for pending events max=4<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); past the pending events for loop, ms=14998<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); Final return of winner<br>[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: made it past the cond test, waitfor returns 14998 <br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: made it past ast_waitfor, ms>0<br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: ast_read returned<br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: <span style="background-color:rgb(255,0,0)">ast_safe_sleep_conditional: ast_read returned NULL, breaking out</span><br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: in while(); <br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: made it past the cond test, about to call waitfor; <br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: ast_waitfor calling ast_waitfor_nandfds()<br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds();n=1, nfds=0<br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); past the first for() statement-- wait full interval<br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); build the pollfd array. rms=14996, AST_MAX_FDS=11<br>[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); Add the individual fds nfds=0<br>[02-Apr-2018 23:31:25.320] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); start= 67108865<br>[02-Apr-2018 23:31:25.320] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); Linux fix <br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); ast_poll returns 0; max=4, kbrms=14996<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: pfds[0].fd = 25; .events=3; .revents=0<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: pfds[1].fd = 26; .events=3; .revents=0<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: pfds[2].fd = 30; .events=3; .revents=0<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: pfds[3].fd = 31; .events=3; .revents=0<br>:<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); cleared flags rms=0, res=0<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: In non-EPOLL ast_waitfor_nandfds(); returning winner early<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: made it past the cond test, waitfor returns 0 <br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: beyond the while()<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: about to lock channel<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: packets queued = 0<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: ast_safe_sleep_conditional: channel unlocked<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] pbx.c: wait_for_hangup, waited 15000 msec<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] pbx.c: wait_for_hangup, returning<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] pbx.c: returned from wait for hangup<br>[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] pbx.c: Spawn extension (Busy, s, 1) exited non-zero on 'SIP/sip-out-5-00000002'<br><br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">So, for some odd reason, the ast_poll call in the ast_waitfor_nandfds routine reports twice that something is waiting in one of the 4 fd's involved. The first one gets a frame from ast_read(),<br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">but the second gets no frame. (Maybe it was partial??)...<br><br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">At any rate, the code in ast_safe_sleep_conditional() says this:<br><br> ms = ast_waitfor(chan, ms);<br> ast_verb(3,"ast_safe_sleep_conditional: made it past the cond test, waitfor returns %d \n", ms);<br> if (ms < 0) {<br> res = -1;<br> break;<br> }<br> if (ms > 0) {<br> ast_verb(3,"ast_safe_sleep_conditional: made it past ast_waitfor, ms>0\n");<br> f = ast_read(chan);<br> ast_verb(3,"ast_safe_sleep_conditional: ast_read returned\n");<br> if (!f) {<br> ast_verb(3,"ast_safe_sleep_conditional: ast_read returned NULL, breaking out\n");<br><span style="background-color:rgb(0,255,255)"> // res = -1;<br> // break;<br> continue; // we still need to finish out the wait!!!!!!!<br></span> }<br> ast_verb(3,"ast_safe_sleep_conditional: ast_read returned a frame\n");<br><br> if (!ast_is_deferrable_frame(f)) {<br> ast_verb(3,"ast_safe_sleep_conditional: the frame is NOT deferrable\n");<br> ast_frfree(f);<br> continue;<br> }<br> ast_verb(3,"ast_safe_sleep_conditional: the frame is deferrable\n");<br><br> if ((dup_f = ast_frisolate(f))) {<br> if (dup_f != f) {<br> ast_frfree(f);<br> }<br> ast_verb(3,"ast_safe_sleep_conditional: inserting the frame in list\n");<br> AST_LIST_INSERT_HEAD(&deferred_frames, dup_f, frame_list);<br> }<br> }<br> }<br><span style="background-color:rgb(0,255,0)"><span></span></span><br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">I commented out the res= -1 and break, and added the continue; instead, as you can see above.<br><br>[02-Apr-2018 23:33:48.234] VERBOSE[21904][C-00000007] pbx.c: Executing [s@Busy:1] Busy("SIP/sip-out-5-00000003", "15") in new stack<br>[02-Apr-2018 23:33:48.235] VERBOSE[21904][C-00000007] pbx.c: in pbx_builtin_busy, about to indicate, data is 15<br>[02-Apr-2018 23:33:48.235] VERBOSE[21904][C-00000007] chan_sip.c: <br><--- Reliably Transmitting (no NAT) to <a href="http://66.23.129.253:5060">66.23.129.253:5060</a> ---><br>SIP/2.0 486 Busy Here<br>Via: SIP/2.0/UDP 66.23.129.253:5060;branch=z9hG4bK7caf.48d7ef727e3bb0c87cbb158c3ef18e63.0;received=66.23.129.253<br>Via: SIP/2.0/UDP 66.23.129.250:5060;received=10.153.1.250;branch=z9hG4bK7caf.de6aa0c534eb22921f9e6f85fa5eb040.0<br>Via: SIP/2.0/UDP 209.193.79.30;branch=z9hG4bK7caf.7a633e1044f70f55d71ce7f568ee5fe0.1<br>Via: SIP/2.0/UDP 67.231.5.112:5060;branch=z9hG4bK00B3ce218f4d0c0d1ca<br>From: "MURPHY STEVE " <<a href="mailto:sip%3A1307xxxxxxx@67.231.5.112">sip:1307xxxxxxx@67.231.5.112</a>>;tag=gK0069f789<br>To: <<a href="mailto:sip%3A15713854677@209.193.79.30">sip:15713854677@209.193.79.30</a>>;tag=as241b593f<br>Call-ID: <a href="mailto:828413536_117349475@67.231.5.112">828413536_117349475@67.231.5.112</a><br>CSeq: 423701 INVITE<br>Server: nexVortex Inc Hosted 3.0 PBX<br>Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE<br>Supported: replaces, timer<br>Content-Length: 0<br><br><br><------------><br>[02-Apr-2018 23:33:48.235] VERBOSE[21904][C-00000007] pbx.c: returned from ast_indicate<br>[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: got lock<br>[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: channel not up, setting hangup cause<br>[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: setting channel to busy<br>[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: unlocked, waiting for handup<br>[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: in wait_for_hangup, data is 15<br>[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] pbx.c: wait_for_hangup, waitsec is: 15<br>[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] pbx.c: wait_for_hangup, waittime is: 15000<br>[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] channel.c: ast_safe_sleep() calling ast_safe_sleep_conditional()<br>[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] channel.c: ast_safe_sleep_conditional: entered, timeout_ms: 15000<br>[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] channel.c: ast_safe_sleep_conditional: in while(); <br>[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] channel.c: ast_safe_sleep_conditional: made it past the cond test, about to call waitfor; <br>[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] channel.c: ast_waitfor calling ast_waitfor_nandfds()<br>....<br><br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">I cut off the rest of the debug, but the call lasts the full 15 seconds after busy() is called, and then hangs up. It's interesting to see what the trunk provider does on top of all this.<br><br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">So, my question is: Did I do the best thing? It seems to work, but I have no idea if I'm creating bugs galore in other usages.<br><br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif">murf<br></div><div class="gmail_default" style="font-family:arial,helvetica,sans-serif"><br clear="all"></div><br>-- <br><div class="gmail_signature"><div dir="ltr"><div><div dir="ltr"><div><div dir="ltr"><div><div dir="ltr"><br>Steve Murphy<br>✉ murf at parsetree dot com<br><br></div></div></div></div></div></div></div></div>
</div>