Re: [asterisk-dev] The "Busy" App.... isn't.
On Thu, Apr 5, 2018 at 9:30 AM, Jared Smith wrote: > On Wed, Apr 4, 2018 at 7:17 PM, Richard Mudgett wrote: >> >> 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. 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 -- _ -- 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
Re: [asterisk-dev] The "Busy" App.... isn't.
On Wed, Apr 4, 2018 at 7:17 PM, Richard Mudgett wrote: > 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 -- _ -- 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
Re: [asterisk-dev] The "Busy" App.... isn't.
On Wed, Apr 4, 2018 at 6:04 PM, Steve Murphy wrote: > > > On Wed, Apr 4, 2018 at 3:20 PM, Matt Fredrickson > wrote: > >> On Mon, Apr 2, 2018 at 9:40 PM, Steve Murphy wrote: >> > Someone complained about errant behavior of the Busy and Hangup apps... >> > and I see some strangenesses that might make them credible. >> > >> >> > >> > 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? >> > > 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 xx" > 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 -- _ -- 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
Re: [asterisk-dev] The "Busy" App.... isn't.
On Wed, Apr 4, 2018, at 8:04 PM, Steve Murphy wrote: > On Wed, Apr 4, 2018 at 3:20 PM, Matt Fredrickson wrote: > > > On Mon, Apr 2, 2018 at 9:40 PM, Steve Murphy wrote: > > > Someone complained about errant behavior of the Busy and Hangup apps... > > > and I see some strangenesses that might make them credible. > > > > > > > > > > > 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? > > > > 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 xx" > 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 -- _ -- 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
Re: [asterisk-dev] The "Busy" App.... isn't.
On Wed, Apr 4, 2018 at 3:20 PM, Matt Fredrickson wrote: > On Mon, Apr 2, 2018 at 9:40 PM, Steve Murphy wrote: > > Someone complained about errant behavior of the Busy and Hangup apps... > > and I see some strangenesses that might make them credible. > > > > > > > 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? > 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 xx" 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 -- _ -- 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
Re: [asterisk-dev] The "Busy" App.... isn't.
On Mon, Apr 2, 2018 at 9:40 PM, Steve Murphy wrote:
> 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-0005] pbx.c: Executing
> [s@Busy:1] Busy("SIP/sip-out-5-0002", "15") in new stack
> [02-Apr-2018 23:31:25.313] VERBOSE[21813][C-0005] pbx.c: in
> pbx_builtin_busy, about to indicate, data is 15
> [02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: returned from
> ast_indicate
> [02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: got lock
> [02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: channel not up,
> setting hangup cause
> [02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: setting channel
> to busy
> [02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: unlocked,
> waiting for handup
> [02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: in
> wait_for_hangup, data is 15
> [02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c:
> wait_for_hangup, waitsec is: 15
> [02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] pbx.c:
> wait_for_hangup, waittime is: 15000
> [02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c:
> ast_safe_sleep() calling ast_safe_sleep_conditional()
> [02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c:
> ast_safe_sleep_conditional: entered, timeout_ms: 15000
> [02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c:
> ast_safe_sleep_conditional: in while();
> [02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] 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-0005] channel.c: ast_waitfor
> calling ast_waitfor_nandfds()
> [02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c: In
> non-EPOLL ast_waitfor_nandfds();n=1, nfds=0
> [02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] 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-0005] 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-0005] channel.c: In
> non-EPOLL ast_waitfor_nandfds(); Add the individual fds nfds=0
> [02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c: In
> non-EPOLL ast_waitfor_nandfds(); start= 67108865
> [02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c: In
> non-EPOLL ast_waitfor_nandfds(); Linux fix
> [02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] 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-0005] channel.c:
> pfds[0].fd = 25; .events=3; .revents=0
> [02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c:
> pfds[1].fd = 26; .events=3; .revents=0
> [02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c:
> pfds[2].fd = 30; .events=3; .revents=0
> [02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c:
> pfds[3].fd = 31; .events=3; .revents=1
> [02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c: In
> non-EPOLL ast_waitfor_nandfds(); cleared flags rms=15000, res=1
> [02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c: In
> non-EPOLL ast_waitfor_nandfds(); check for pending events max=4
> [02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] 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-0005] channel.c: In
> non-EPOLL ast_waitfor_nandfds(); Final return of winner
> [02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] 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-0005] channel.c:
> ast_safe_sleep_conditional: made it past ast_waitfor, ms>0
> [02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] channel.c:
> ast_safe_sleep_conditional: ast_read returned
> [02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] channel.c:
> ast_safe_sleep_conditional: ast_read returned a frame
> [02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] channel.c:
> ast_safe_sleep_conditional: the frame is NOT deferrable
> [02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] channel.c:
> ast_safe_sleep_conditional: in while();
> [02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] channel.c:
>
[asterisk-dev] The "Busy" App.... isn't.
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-0005] pbx.c: Executing
[s@Busy:1] Busy("SIP/sip-out-5-0002", "15") in new stack
[02-Apr-2018 23:31:25.313] VERBOSE[21813][C-0005] pbx.c: in
pbx_builtin_busy, about to indicate, data is 15
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: returned from
ast_indicate
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: got lock
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: channel not
up, setting hangup cause
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: setting
channel to busy
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: unlocked,
waiting for handup
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c: in
wait_for_hangup, data is 15
[02-Apr-2018 23:31:25.314] VERBOSE[21813][C-0005] pbx.c:
wait_for_hangup, waitsec is: 15
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] pbx.c:
wait_for_hangup, waittime is: 15000
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c:
ast_safe_sleep() calling ast_safe_sleep_conditional()
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c:
ast_safe_sleep_conditional: entered, timeout_ms: 15000
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c:
ast_safe_sleep_conditional: in while();
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] 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-0005] channel.c:
ast_waitfor calling ast_waitfor_nandfds()
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c: In
non-EPOLL ast_waitfor_nandfds();n=1, nfds=0
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] 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-0005] 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-0005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); Add the individual fds nfds=0
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); start= 67108865
[02-Apr-2018 23:31:25.315] VERBOSE[21813][C-0005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); Linux fix
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] 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-0005] channel.c:
pfds[0].fd = 25; .events=3; .revents=0
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c:
pfds[1].fd = 26; .events=3; .revents=0
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c:
pfds[2].fd = 30; .events=3; .revents=0
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c:
pfds[3].fd = 31; .events=3; .revents=1
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); cleared flags rms=15000, res=1
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); check for pending events max=4
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] 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-0005] channel.c: In
non-EPOLL ast_waitfor_nandfds(); Final return of winner
[02-Apr-2018 23:31:25.316] VERBOSE[21813][C-0005] 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-0005] channel.c:
ast_safe_sleep_conditional: made it past ast_waitfor, ms>0
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] channel.c:
ast_safe_sleep_conditional: ast_read returned
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] channel.c:
ast_safe_sleep_conditional:
ast_read returned a frame
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] channel.c:
ast_safe_sleep_conditional: the frame is NOT deferrable
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] channel.c:
ast_safe_sleep_conditional: in while();
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-0005] 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-0005] channel.c:
ast_waitfor calling ast_waitfor_nandfds()
[02-Apr-2018 23:31:25.317] VERBOSE[21813][C-00
