[asterisk-dev] The "Busy" App.... isn't.
Steve Murphy
murf at parsetree.com
Mon Apr 2 21:40:09 CDT 2018
Someone complained about errant behavior of the Busy and Hangup apps...
and I see some strangenesses that might make them credible.
Boy, did I have to chase this around to find what I think is the problem!
What happens: The (eg) Busy app is called. Instead of it waiting a generous
15 seconds,
it immediately hangs up, not forwarding anything to the trunk the call came
in from. This
is the closing act in the blocking of a call, executed from the dialplan.
With a generous amount of debug added to help explain the order of
execution, I see
this:
[02-Apr-2018 23:31:25.313] VERBOSE[21813][C-00000005] pbx.c: Executing
[s at Busy:1] Busy("SIP/sip-out-5-00000002", "15") in new stack
[02-Apr-2018 23:31:25.313] VERBOSE[21813][C-00000005] pbx.c: in
pbx_builtin_busy, about to indicate, data is 15
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: returned from
ast_indicate
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: got lock
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: channel not
up, setting hangup cause
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: setting
channel to busy
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: unlocked,
waiting for handup
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c: in
wait_for_hangup, data is 15
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-00000005] pbx.c:
wait_for_hangup, waitsec is: 15
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] pbx.c:
wait_for_hangup, waittime is: 15000
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep() calling ast_safe_sleep_conditional()
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: entered, timeout_ms: 15000
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: in while();
[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;
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c:
ast_waitfor calling ast_waitfor_nandfds()
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds();n=1, nfds=0
[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
[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
[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
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); start= 67108865
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); Linux fix
[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
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c:
pfds[0].fd = 25; .events=3; .revents=0
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c:
pfds[1].fd = 26; .events=3; .revents=0
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c:
pfds[2].fd = 30; .events=3; .revents=0
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c:
pfds[3].fd = 31; .events=3; .revents=1
[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
[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
[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
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); Final return of winner
[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
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: made it past ast_waitfor, ms>0
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: ast_read returned
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional:
ast_read returned a frame
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: the frame is NOT deferrable
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: in while();
[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;
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c:
ast_waitfor calling ast_waitfor_nandfds()
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds();n=1, nfds=0
[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
[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
[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
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); start= 67108865
[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); Linux fix
[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
[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c:
pfds[0].fd = 25; .events=3; .revents=0
[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c:
pfds[1].fd = 26; .events=3; .revents=0
[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c:
pfds[2].fd = 30; .events=3; .revents=0
[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c:
pfds[3].fd = 31; .events=3; .revents=1
[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
[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
[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
[02-Apr-2018 23:31:25.318] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); Final return of winner
[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
[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: made it past ast_waitfor, ms>0
[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: ast_read returned
[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional:
ast_read returned NULL, breaking out
[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: in while();
[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;
[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c:
ast_waitfor calling ast_waitfor_nandfds()
[02-Apr-2018 23:31:25.319] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds();n=1, nfds=0
[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
[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
[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
[02-Apr-2018 23:31:25.320] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); start= 67108865
[02-Apr-2018 23:31:25.320] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); Linux fix
[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
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c:
pfds[0].fd = 25; .events=3; .revents=0
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c:
pfds[1].fd = 26; .events=3; .revents=0
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c:
pfds[2].fd = 30; .events=3; .revents=0
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c:
pfds[3].fd = 31; .events=3; .revents=0
:
[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
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); returning winner early
[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
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: beyond the while()
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: about to lock channel
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: packets queued = 0
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] channel.c:
ast_safe_sleep_conditional: channel unlocked
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] pbx.c:
wait_for_hangup, waited 15000 msec
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] pbx.c:
wait_for_hangup, returning
[02-Apr-2018 23:31:40.328] VERBOSE[21813][C-00000005] pbx.c: returned from
wait for hangup
[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'
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(),
but the second gets no frame. (Maybe it was partial??)...
At any rate, the code in ast_safe_sleep_conditional() says this:
ms = ast_waitfor(chan, ms);
ast_verb(3,"ast_safe_sleep_conditional: made it past the
cond test, waitfor returns %d \n", ms);
if (ms < 0) {
res = -1;
break;
}
if (ms > 0) {
ast_verb(3,"ast_safe_sleep_conditional: made it
past ast_waitfor, ms>0\n");
f = ast_read(chan);
ast_verb(3,"ast_safe_sleep_conditional: ast_read
returned\n");
if (!f) {
ast_verb(3,"ast_safe_sleep_conditional:
ast_read returned NULL, breaking out\n");
// res = -1;
// break;
continue; // we still need to finish out
the wait!!!!!!!
}
ast_verb(3,"ast_safe_sleep_conditional: ast_read
returned a frame\n");
if (!ast_is_deferrable_frame(f)) {
ast_verb(3,"ast_safe_sleep_conditional: the
frame is NOT deferrable\n");
ast_frfree(f);
continue;
}
ast_verb(3,"ast_safe_sleep_conditional: the frame
is deferrable\n");
if ((dup_f = ast_frisolate(f))) {
if (dup_f != f) {
ast_frfree(f);
}
ast_verb(3,"ast_safe_sleep_conditional:
inserting the frame in list\n");
AST_LIST_INSERT_HEAD(&deferred_frames,
dup_f, frame_list);
}
}
}
I commented out the res= -1 and break, and added the continue; instead, as
you can see above.
[02-Apr-2018 23:33:48.234] VERBOSE[21904][C-00000007] pbx.c: Executing
[s at Busy:1] Busy("SIP/sip-out-5-00000003", "15") in new stack
[02-Apr-2018 23:33:48.235] VERBOSE[21904][C-00000007] pbx.c: in
pbx_builtin_busy, about to indicate, data is 15
[02-Apr-2018 23:33:48.235] VERBOSE[21904][C-00000007] chan_sip.c:
<--- Reliably Transmitting (no NAT) to 66.23.129.253:5060 --->
SIP/2.0 486 Busy Here
Via: SIP/2.0/UDP 66.23.129.253:5060
;branch=z9hG4bK7caf.48d7ef727e3bb0c87cbb158c3ef18e63.0;received=66.23.129.253
Via: SIP/2.0/UDP 66.23.129.250:5060
;received=10.153.1.250;branch=z9hG4bK7caf.de6aa0c534eb22921f9e6f85fa5eb040.0
Via: SIP/2.0/UDP
209.193.79.30;branch=z9hG4bK7caf.7a633e1044f70f55d71ce7f568ee5fe0.1
Via: SIP/2.0/UDP 67.231.5.112:5060;branch=z9hG4bK00B3ce218f4d0c0d1ca
From: "MURPHY STEVE " <sip:1307xxxxxxx at 67.231.5.112>;tag=gK0069f789
To: <sip:15713854677 at 209.193.79.30>;tag=as241b593f
Call-ID: 828413536_117349475 at 67.231.5.112
CSeq: 423701 INVITE
Server: nexVortex Inc Hosted 3.0 PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0
<------------>
[02-Apr-2018 23:33:48.235] VERBOSE[21904][C-00000007] pbx.c: returned from
ast_indicate
[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: got lock
[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: channel not
up, setting hangup cause
[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: setting
channel to busy
[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: unlocked,
waiting for handup
[02-Apr-2018 23:33:48.236] VERBOSE[21904][C-00000007] pbx.c: in
wait_for_hangup, data is 15
[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] pbx.c:
wait_for_hangup, waitsec is: 15
[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] pbx.c:
wait_for_hangup, waittime is: 15000
[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] channel.c:
ast_safe_sleep() calling ast_safe_sleep_conditional()
[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] channel.c:
ast_safe_sleep_conditional: entered, timeout_ms: 15000
[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] channel.c:
ast_safe_sleep_conditional: in while();
[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;
[02-Apr-2018 23:33:48.237] VERBOSE[21904][C-00000007] channel.c:
ast_waitfor calling ast_waitfor_nandfds()
....
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.
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.
murf
--
Steve Murphy
✉ murf at parsetree dot com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-dev/attachments/20180402/56820a43/attachment-0001.html>
More information about the asterisk-dev
mailing list