[Home]

Summary:ASTERISK-07205: CAN NOT Hangup channel in time.
Reporter:Jin Ke Jiang (jjk)Labels:
Date Opened:2006-06-20 01:51:38Date Closed:2006-11-20 20:43:51.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_dial
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) delay.log
( 1) hangup_delay.log
( 2) SVN-trunk-r36148.log
( 3) tracelog
( 4) two_test_debug_log,_not_hangup_in_time.txt
Description:I found that Asterisk can't hangup the channel in time in the following situation.

I set up two asterisk server, one in 192.168.0.166, the other in 192.168.0.40

I open a sipphone on my own machine, login to the 192.168.0.166 asterisk, then call 600. 600 is a echo app in 192.168.0.40.
Press one of the number on the phone, then the phone will send DTMF to the Asterisk server, then leave my computer, so there will be no rtp to the Asterisk server now. Wait for 60 seconds, and I saw the call will not hangup in time (60 seconds) after the callee answered.

I tried the SetAbsoluteTimeOut(60), Set(TIMEOUT(absolute)=60), still got the same. I also tried in the Dial option, S(60), L(60000:0:0), L(60000:61000:30000), and got the same result.

It seems it's a bug in the timer of the channel, gets interrupted by the dtmf code.

Let's conclude in a short word about this issue.
For example.
Dial an extension, limit the calltime to 60 seconds
Send dtmf to that extension, then be quite(no rtp transfered)
the call will not auto hangup in 60 seconds after the callee pick up the phone.


****** ADDITIONAL INFORMATION ******

in 192.168.0.40
extensions.conf
[from-sip-external]
exten => 600,1,Ringing
exten => 600,n,Answer
exten => 600,n,Echo
exten => 600,n,Hangup

in 192.168.0.166
sip.conf
[general]
context=from-sip-external
bindport=5082  ; Asterisk 1.2 used
bindaddr=0.0.0.0
srvlookup=yes

realm=test.cc.com
useragent=CallingCard Platform

disallow=all
allow=alaw

rtptimeout=300
rtpholdtimeout=300
maxexpirey=3600
defaultexpirey=600
canreinvite=yes
tos=lowdelay

trustrpid = no
sendrpid = yes

[9901]
username=9901
canreinvite=no
context=localuser
host=dynamic
nat=1
secret=123456
type=friend
disallow=all
allow=alaw
regseconds=300
cancallforward=yes


extensions.conf
[bogon-calls]
;
; Take unknown callers that may have found in
; our system, and send them to a re-order tone.
; The string "_." matches any dialed sequence, so all
; calls will result in the Congestion tone application
; being called. They'll get bored and hang up eventually.
;
exten => _.,1,AbsoluteTimeout(15)
exten => _.,2,Congestion
exten => _.,3,Hangup

[default]
;give external users congestion and hangup
include => bogon-calls

[from-sip-external]
;give external users congestion and hangup
include => bogon-calls

[localuser]
;exten => 600,1,Set(TIMEOUT(absolute)=60)
exten => 600,1,Dial(SIP/${EXTEN}@192.168.0.40:5082,60|S(60))
exten => 600,n,Hangup
Comments:By: Jin Ke Jiang (jjk) 2006-06-20 02:00:39

The second attached file is the debug log. The first one is not corretly formatted. Please ignore that.
By: Serge Vecher (serge-v) 2006-06-20 09:28:27

jjk: verbose log needs to be turned on as well. Start asterisk with "asterisk -vvvvddddc" (add whatever other options you need). Enable sip debug on console and try again.
By: Jin Ke Jiang (jjk) 2006-06-20 23:26:16

another debug log uploaded with sip debug turned on.
By: Jin Ke Jiang (jjk) 2006-06-21 21:44:02

This issue is similar to issue 0006356.
By: Serge Vecher (serge-v) 2006-06-22 14:06:44

hmm, weird. The first log says verbosity is at least 4, but there is no verbose log :-|

1) Make sure your logger.conf has the following line:
  console => notice,warning,error,debug
2) Restart Asterisk
3) Enable SIP transaction logging with the following CLI commands:
set debug 4
set verbose 4
sip debug
4) Capture the console output at try again. Thanls
By: Jin Ke Jiang (jjk) 2006-06-22 23:19:14

I get the log from the log directory of asterisk, not on the console.
I sent another log according to your requirement 'hangup_delay.log'.
By: Jin Ke Jiang (jjk) 2006-06-28 02:31:36

SVN-trunk-r36148 is a log file of SVN-trunk-r36148.
I've add some debug in channel.c
static enum ast_bridge_result ast_generic_bridge()

Why the "who = ast_waitfor_n(cs, 2, &to);" will have 3 second delay ?

code snap from the above function:

               /* Calculate the appropriate max sleep interval - in general, this is the time,
                  left to the closest jb delivery moment */
               if (jb_in_use)
                       to = ast_jb_get_when_to_wakeup(c0, c1, to);
               ast_log(LOG_DEBUG, "before ast_waitfor_n(cs, 2, &%d);\n", to);
               who = ast_waitfor_n(cs, 2, &to);
               ast_log(LOG_DEBUG, "after ast_waitfor_n(cs, 2, &%d);\n", to);
By: Jin Ke Jiang (jjk) 2006-07-01 04:22:36

I've added some debug log in the
'struct ast_channel *ast_waitfor_nandfds' function inside channel.c

I found there is delay in the poll system call.
I'm using linux x86-32, so I found the delay is in the first poll().
Is there anyone has any clue to fix this ?

Please check the delay.log in the attach for the test result.

       if (sizeof(int) == 4) { /* XXX fix timeout > 600000 on linux x86-32 */
               ast_log(LOG_DEBUG, "check point 3\n");
               do {
                       int kbrms = rms;
                       ast_log(LOG_DEBUG, "kbrms: %d, max: %d\n", kbrms, max);
                       if (kbrms > 600000)
                               kbrms = 600000;
                       res = poll(pfds, max, kbrms);
                       ast_log(LOG_DEBUG, "check point 4\n");
                       if (!res)
                               rms -= kbrms;
               } while (!res && (rms > 0));
       } else {
               res = poll(pfds, max, rms);
               ast_log(LOG_DEBUG, "check point 5\n");
       }


By: Jin Ke Jiang (jjk) 2006-07-17 23:03:53

the correct S(x) timeout should be caused by the code inside ast_waitfor_nandfds(), the rms is miscalculated in the svn code. But it's correctly calculated in the release version. So please fix this.

in svn-37875 code
channel.c
  1662         /* Wait full interval */
  1663         rms = *ms;
  1664         if (whentohangup) {
  1665                 rms = (whentohangup - now) * 1000;      /* timeout in milliseconds */
  1666                 if (*ms >= 0 && *ms < rms)              /* original *ms still smaller */
  1667                         rms =  *ms;
  1668         }


in 1.2.10

channel.c
  1556         rms = *ms;
  1557
  1558         if (havewhen) {
  1559                 if ((*ms < 0) || (whentohangup * 1000 < *ms)) {
  1560                         rms =  whentohangup * 1000;
  1561                 }
  1562         }


Another problem, the L option of the Dial app still has delay. After applying the patch of issue 6356, the L option works properly. This happens both in svn and release version of asterisk.


By: Kaloyan Kovachev (knk) 2006-08-18 12:18:59

had the same problem and did the same debug changes, before to find this one :(
the delay in poll is a problem on linux x86_64 too.
in my case, this happens when feature timer is activated and on DTMF it creates its own bridge. then if L option is used i don't hear the warning sound as the new bridge does not keep the nexteventts and timelimit, so the call is not closed either. If a second DTMF is received some time later (but after feature_timeout) i can see both of them as being received again (with dtmf logging on console enabled) and then asterisk jumps out that bridge, then if the old nexteventts has passed i hear the time left, so the problem is that delay in poll() and probably nothing to do with rms calculation
By: Serge Vecher (serge-v) 2006-09-06 12:10:56

ok, so do we have a patch to remedy the situation here?
By: Kaloyan Kovachev (knk) 2006-09-11 01:47:45

Not sure if the delay in poll is still present (after the VLDTMF changes), but now if DTMF is received (on any of the channels) after the first warning - new warning is played each time.

The call is not hangup in time (without the patch from 7531) with L(60000:30000:20000) - 70s long

If the digit received is part of a feature code (in my case '#1' is blind transfer and i have pressed '#' only) the call is not hangup in time, but after 75s with the same L values and with the patch applied.
If the digit is not part of a feature code or another digit is received after the feature timeout, then everithing is OK, so it is something to do with the feature timeout somehow. If it is possible to schedule a null (dtmf) frame to be queued after the feature timeout, it may jump out of the feature bridge back to the first one where the limit and warning time are present?
By: Serge Vecher (serge-v) 2006-09-13 09:32:19

well, VLDTMF code only went into trunk. What about 1.2.x?
By: Kaloyan Kovachev (knk) 2006-09-14 01:36:54

Not sure about 1.2.x, but with r13279 (which i am running) is working fine. I guess the problem was introduced with the bugfix for feature timeout.
<quote>If it is possible to schedule a null (dtmf) frame to be queued after the feature timeout, it may jump out of the feature bridge back to the first one where the limit and warning time are present?</quote> - this is the only workaroud i can think of.
By: jmls (jmls) 2006-11-01 12:50:03.000-0600

so, can we close this ?
By: Joshua C. Colp (jcolp) 2006-11-20 20:43:50.000-0600

As far as I can tell this issue is fixed and no new activity is happening here... so I'm closing this out. If there still is an issue we need to solve, feel free to reopen or open a new bug with detailed information. Thanks all!