[asterisk-dev] The "Busy" App.... isn't.

Discussion:

Steve Murphy

2018-04-03 02:40:09 UTC

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
[***@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
[***@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:***@67.231.5.112>;tag=gK0069f789
To: <sip:***@209.193.79.30>;tag=as241b593f
Call-ID: ***@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

Matt Fredrickson

2018-04-04 21:20:56 UTC

Permalink

Post by Steve Murphy
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
[02-Apr-2018 23:31:25.313] VERBOSE[21813][C-00000005] pbx.c: Executing
[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
wait_for_hangup, waitsec is: 15
wait_for_hangup, waittime is: 15000
ast_safe_sleep() calling ast_safe_sleep_conditional()
ast_safe_sleep_conditional: entered, timeout_ms: 15000
ast_safe_sleep_conditional: in while();
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
pfds[0].fd = 25; .events=3; .revents=0
pfds[1].fd = 26; .events=3; .revents=0
pfds[2].fd = 30; .events=3; .revents=0
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
ast_safe_sleep_conditional: made it past the cond test, waitfor returns
15000
ast_safe_sleep_conditional: made it past ast_waitfor, ms>0
ast_safe_sleep_conditional: ast_read returned
ast_safe_sleep_conditional: ast_read returned a frame
ast_safe_sleep_conditional: the frame is NOT deferrable
ast_safe_sleep_conditional: in while();
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
pfds[0].fd = 25; .events=3; .revents=0
pfds[1].fd = 26; .events=3; .revents=0
pfds[2].fd = 30; .events=3; .revents=0
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
ast_safe_sleep_conditional: made it past the cond test, waitfor returns
14998
ast_safe_sleep_conditional: made it past ast_waitfor, ms>0
ast_safe_sleep_conditional: ast_read returned
ast_safe_sleep_conditional: ast_read returned NULL, breaking out
ast_safe_sleep_conditional: in while();
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
pfds[0].fd = 25; .events=3; .revents=0
pfds[1].fd = 26; .events=3; .revents=0
pfds[2].fd = 30; .events=3; .revents=0
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
ast_safe_sleep_conditional: made it past the cond test, waitfor returns 0
ast_safe_sleep_conditional: beyond the while()
ast_safe_sleep_conditional: about to lock channel
ast_safe_sleep_conditional: packets queued = 0
ast_safe_sleep_conditional: channel unlocked
wait_for_hangup, waited 15000 msec
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??)...
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_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);
}
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
[02-Apr-2018 23:33:48.235] VERBOSE[21904][C-00000007] pbx.c: in
pbx_builtin_busy, about to indicate, data is 15
<--- 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
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
wait_for_hangup, waitsec is: 15
wait_for_hangup, waittime is: 15000
ast_safe_sleep() calling ast_safe_sleep_conditional()
ast_safe_sleep_conditional: entered, timeout_ms: 15000
ast_safe_sleep_conditional: in while();
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.

There is an assumption (for asterisk C level applications, like
Busy()) when using ast_read that if it ever returns NULL that the
underlying channel has been hung up and the application should quickly
exit. Busy() is honoring that assumption. It looks like in
sip_indicate() of chan_sip.c, when a AST_CONTROL_BUSY is queued on a
SIP channel, it sets the soft hangup flag on the channel. That's why
you're seeing this behavior. The timeout from Busy() is invalidated
if the underlying channel wants to be hung up.

I would be highly concerned about breaking that assumption, as you are
doing in your proposed patch. Is there a particular reason you want
to keep the call up for 15 seconds before releasing the channel?
--
Matthew Fredrickson
Digium, Inc. | Engineering Manager
445 Jan Davis Drive NW - Huntsville, AL 35806 - USA

--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

asterisk-dev mailing list
To UNSUBSCRIBE or update options visit:
http://lists.digium.com/mailman/listinfo/asterisk-dev

Steve Murphy

2018-04-04 23:04:30 UTC

Permalink

Post by Steve Murphy
Someone complained about errant behavior of the Busy and Hangup apps...
and I see some strangenesses that might make them credible.

â<snip>

Post by Steve Murphy
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

Post by Steve Murphy
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

Post by Steve Murphy
idea if I'm creating bugs galore in other usages.

There is an assumption (for asterisk C level applications, like
Busy()) when using ast_read that if it ever returns NULL that the
underlying channel has been hung up and the application should quickly
exit. Busy() is honoring that assumption. It looks like in
sip_indicate() of chan_sip.c, when a AST_CONTROL_BUSY is queued on a
SIP channel, it sets the soft hangup flag on the channel. That's why
you're seeing this behavior. The timeout from Busy() is invalidated
if the underlying channel wants to be hung up.
I would be highly concerned about breaking that assumption, as you are
doing in your proposed patch. Is there a particular reason you want
to keep the call up for 15 seconds before releasing the channel?

âI was tempted so say:â

âMainly for the sake of that "Busy Here" SIP message I'd like to see go
back to the
trunk provider. With my patch, it goes out. Without it, nada.

But... incoming calls can come from either of two IP's, and "sip set debug
ip xxxxxx"
can only monitor one. So, what I thought was happening may not be!

But, really.... if the Busy app takes an arg, but never honors it... why
does it take the
argument at all?

murf

--
Steve Murphy
â murf at parsetree dot com

Joshua Colp

2018-04-04 23:09:13 UTC

Permalink

Post by Steve Murphy
Someone complained about errant behavior of the Busy and Hangup apps...
and I see some strangenesses that might make them credible.

<snip>

Post by Steve Murphy
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

Post by Steve Murphy
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

Post by Steve Murphy
idea if I'm creating bugs galore in other usages.

There is an assumption (for asterisk C level applications, like
Busy()) when using ast_read that if it ever returns NULL that the
underlying channel has been hung up and the application should quickly
exit. Busy() is honoring that assumption. It looks like in
sip_indicate() of chan_sip.c, when a AST_CONTROL_BUSY is queued on a
SIP channel, it sets the soft hangup flag on the channel. That's why
you're seeing this behavior. The timeout from Busy() is invalidated
if the underlying channel wants to be hung up.
I would be highly concerned about breaking that assumption, as you are
doing in your proposed patch. Is there a particular reason you want
to keep the call up for 15 seconds before releasing the channel?

I was tempted so say:
Mainly for the sake of that "Busy Here" SIP message I'd like to see go
back to the
trunk provider. With my patch, it goes out. Without it, nada.
But... incoming calls can come from either of two IP's, and "sip set debug
ip xxxxxx"
can only monitor one. So, what I thought was happening may not be!
But, really.... if the Busy app takes an arg, but never honors it... why
does it take the
argument at all?

Legacy purposes where it's not signaled I'd bet. Specifically, when the busy tone itself is generated locally.
--
Joshua Colp
Digium, Inc. | Senior Software Developer
445 Jan Davis Drive NW - Huntsville, AL 35806 - US
Check us out at: www.digium.com & www.asterisk.org

Richard Mudgett

2018-04-04 23:17:04 UTC

Permalink

Post by Steve Murphy

Post by Steve Murphy
Someone complained about errant behavior of the Busy and Hangup apps...
and I see some strangenesses that might make them credible.

â<snip>

Post by Steve Murphy
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

Post by Steve Murphy
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

Post by Steve Murphy
idea if I'm creating bugs galore in other usages.

There is an assumption (for asterisk C level applications, like
Busy()) when using ast_read that if it ever returns NULL that the
underlying channel has been hung up and the application should quickly
exit. Busy() is honoring that assumption. It looks like in
sip_indicate() of chan_sip.c, when a AST_CONTROL_BUSY is queued on a
SIP channel, it sets the soft hangup flag on the channel. That's why
you're seeing this behavior. The timeout from Busy() is invalidated
if the underlying channel wants to be hung up.
I would be highly concerned about breaking that assumption, as you are
doing in your proposed patch. Is there a particular reason you want
to keep the call up for 15 seconds before releasing the channel?

âI was tempted so say:â
âMainly for the sake of that "Busy Here" SIP message I'd like to see go
back to the
trunk provider. With my patch, it goes out. Without it, nada.
But... incoming calls can come from either of two IP's, and "sip set debug
ip xxxxxx"
can only monitor one. So, what I thought was happening may not be!
But, really.... if the Busy app takes an arg, but never honors it... why
does it take the
argument at all?

The argument is used when the channel is already answered. The channel
will then send
the busy tone inband for the specified number of seconds and hangup. The
behavior also
depends upon the channel driver.

exten = _X.,1,NoOp()
same = n,Answer()
same = n,Busy(15)
same = n,Hangup()

Richard

Jared Smith

2018-04-05 14:30:12 UTC

Permalink

Post by Richard Mudgett
The argument is used when the channel is already answered. The channel
will then send
the busy tone inband for the specified number of seconds and hangup. The
behavior also
depends upon the channel driver.
exten = _X.,1,NoOp()
same = n,Answer()
same = n,Busy(15)
same = n,Hangup()

My understand is, at least for some channel drivers/technologies, that it
should also work when the channel is *not* answered, because answering the
call can mess up your CDR records. My guess is that's what Steve is trying
to accomplish here... signal that the "line" is busy and can't be answered,
without actually answering the call.

-Jared

Matt Fredrickson

2018-04-05 15:57:37 UTC

Permalink

Post by Jared Smith

In the case of chan_sip (which it looks like he's using), this is
actually what happens (and happened). If you use the Busy()
application prior to the call being Answer()'d, it sets back the 486
Busy Here indication (as per his original debug). As a side affect,
since the call is over at this point, this also hangs the channel up
immediately as well.

As mentioned previously, if he were to Answer() the call first, I
think it would wait the 15 seconds desired and play busy tones
in-band.
--
Matthew Fredrickson
Digium, Inc. | Engineering Manager
445 Jan Davis Drive NW - Huntsville, AL 35806 - USA