| Summary: | ASTERISK-07351: rtptimeout setting fails to hang up a call dialed with AGI script | ||
| Reporter: | chrisde (chrisde) | Labels: | |
| Date Opened: | 2006-07-18 02:23:29 | Date Closed: | 2011-06-07 14:02:45 |
| Priority: | Major | Regression? | No |
| Status: | Closed/Complete | Components: | Core/General |
| Versions: | Frequency of Occurrence | ||
| Related Issues: | |||
| Environment: | Attachments: | ||
| Description: | Why is asterisk keeping channels up when "...Nobody there, continuing...". And what happened there? Won't Asterisk hangup when the user pulls the line out of the wall? Or when the user looses signal from his Accesspoint using a WLAN phone? Also whenever I look in the console and type "show channels" there are several channels up, that shouldn't be up. Also there are channels in state ring for more than 16 hours while the caller isn't registerd anymore with asterisk. ****** ADDITIONAL INFORMATION ****** Jul 15 16:52:51 VERBOSE[18440] logger.c: -- Executing DeadAGI("SIP/mysipid-3d7b", "newalepo.php") in new stack Jul 15 16:52:51 VERBOSE[18440] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/newalepo.php Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_request' => 'newalepo.php' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_channel' => 'SIP/mysipid-3d7b' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_language' => 'en' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_type' => 'SIP' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_uniqueid' => '1152982371.5285' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_callerid' => 'mysipid' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_calleridname' => 'mysipid' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_callingpres' => '0' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_callingani2' => '0' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_callington' => '0' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_callingtns' => '0' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_dnid' => '92215616237' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_rdnis' => 'unknown' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_context' => 'contextsip' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_extension' => '92215616237' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_priority' => '1' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_enhanced' => '0.0' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: 'agi_accountcode' => 'mysipid' Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: string(96) "mysipid ; SIP/mysipid-3d7b ; 1152982371.5285 ; mysipid ; 0092215616237 ; 92215616237"n Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: >> SET AUTOHANGUP 3600 Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: >> SET CALLERID Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: >> EXEC DIAL sip/70092215616237 at 217.111.25.154 Jul 15 16:52:51 VERBOSE[18440] logger.c: -- AGI Script Executing Application: (DIAL) Options: (sip/70092215616237 at 217.111.25.154) Jul 15 16:52:51 DEBUG[18440] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipfriends WHERE name = '217.111.25.154' Jul 15 16:52:51 DEBUG[18440] res_config_mysql.c: MySQL RealTime: Everything is fine. Jul 15 16:52:51 DEBUG[18440] chan_sip.c: Outgoing Call for 70092215616237 Jul 15 16:52:51 VERBOSE[18440] logger.c: -- Called 70092215616237 at 217.111.25.154 Jul 15 16:53:06 VERBOSE[18440] logger.c: -- SIP/217.111.25.154-bb31 is making progress passing it to SIP/mysipid-3d7b Jul 15 16:53:07 DEBUG[18440] chan_sip.c: Oooh, format changed to 2 Jul 15 16:53:09 NOTICE[18440] rtp.c: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: 217.111.25.154 Jul 15 16:53:17 VERBOSE[18440] logger.c: -- SIP/217.111.25.154-bb31 is making progress passing it to SIP/mysipid-3d7b Jul 15 16:54:02 VERBOSE[18440] logger.c: -- SIP/217.111.25.154-bb31 answered SIP/mysipid-3d7b Jul 15 16:54:02 VERBOSE[18440] logger.c: -- Attempting native bridge of SIP/mysipid-3d7b and SIP/217.111.25.154-bb31 Jul 15 17:52:51 DEBUG[18440] channel.c: Nobody there, continuing... Jul 15 17:52:51 DEBUG[18440] channel.c: Nobody there, continuing... Jul 15 17:52:51 DEBUG[18440] channel.c: Nobody there, continuing... Jul 15 17:52:51 DEBUG[18440] channel.c: Nobody there, continuing... . . . repeated 2 million times ... ... Jul 15 17:52:51 DEBUG[18440] channel.c: Nobody there, continuing... Jul 15 17:52:51 DEBUG[18440] channel.c: Nobody there, continuing... Jul 15 17:52:51 DEBUG[18440] channel.c: Nobody there, continuing... Jul 15 18:05:45 DEBUG[18440] channel.c: Didn't get a frame from channel: SIP/217.111.25.154-bb31 Jul 15 18:05:45 DEBUG[18440] channel.c: Bridge stops bridging channels SIP/mysipid-3d7b and SIP/217.111.25.154-bb31 Jul 15 18:05:45 DEBUG[18440] chan_sip.c: update_call_counter(70092215616237) - decrement call limit counter Jul 15 18:05:45 DEBUG[18440] app_dial.c: Exiting with DIALSTATUS=ANSWER. Jul 15 18:05:45 VERBOSE[18440] logger.c: newalepo.php: >> GET VARIABLE ANSWEREDTIME Jul 15 18:05:45 VERBOSE[18440] logger.c: newalepo.php: >> GET VARIABLE DIALSTATUS Jul 15 18:05:45 VERBOSE[18440] logger.c: newalepo.php: string(6) "ANSWER"n Jul 15 18:05:45 VERBOSE[18440] logger.c: -- AGI Script newalepo.php completed, returning 0 Jul 15 18:05:45 DEBUG[18440] pbx.c: Extension 92215616237, priority 1 returned normally even though call was hung up Jul 15 18:05:45 DEBUG[18440] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Jul 15 18:05:45 DEBUG[18440] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2006-07-15 16:52:51','\"mysipid\" <mysipid>','mysipid','92215616237','contextsip', 'SIP/mysipid-3d7b','SIP/217.111.25.154-bb31','Dial','sip/70092215616237 at 217.111.25.154',4374,4303,'ANSWERED',3,'mysipid') Jul 15 18:05:45 DEBUG[18440] chan_sip.c: update_call_counter(mysipid) - decrement call limit counter | ||
| Comments: | By: chrisde (chrisde) 2006-07-18 03:41:00 please also take note of "SET AUTOHANGUP 3600" ... Asterisk seems to also ignore this. By: Serge Vecher (serge-v) 2006-07-18 08:56:41 1. First of all, you are using an AGI script to dial. If you dial directly with Dial(), I bet this problem won't happen. 2. if the device looses network connectivity, there is a setting in sip.conf to specifically address this - 'rtptimeout' You have posted a bug report marked 'major' that has to do with a custom component, rather than Asterisk proper, which could also be addressed with a configuration option. This is the second time you do this. In the future, if you think you have identified an Asterisk bug, please consult somebody else either on #asterisk channel on IRC or asterisk-users mailing list. Thank you. By: chrisde (chrisde) 2006-07-22 06:07:16 This problem occurs having rtptimeout set to 60 seconds. Also on the mailing-list and in #asterisk there are no ideas for this problem. Also I upgraded to 1.2.10 without any change. This night asterisk crashed completely because of this closing the channel on restart: Jul 22 01:36:02 DEBUG[11595] chan_sip.c: Outgoing Call for 700554333296999 Jul 22 01:36:02 VERBOSE[11595] logger.c: -- Called 700554333296999 at 217.111.25.154 Jul 22 01:36:06 VERBOSE[11595] logger.c: -- SIP/217.111.25.154-08201fe8 is making progress passing it to SIP/mysipid-08215dc8 Jul 22 01:36:07 DEBUG[11595] chan_sip.c: Oooh, format changed to 2 Jul 22 01:36:07 NOTICE[11595] rtp.c: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: 217.111.25.154 Jul 22 01:36:21 VERBOSE[11595] logger.c: -- SIP/217.111.25.154-08201fe8 answered SIP/mysipid-08215dc8 Jul 22 01:36:21 VERBOSE[11595] logger.c: -- Attempting native bridge of SIP/mysipid-08215dc8 and SIP/217.111.25.154-08201fe8 Jul 22 02:36:02 DEBUG[11595] channel.c: Nobody there, continuing... Jul 22 02:36:02 DEBUG[11595] channel.c: Nobody there, continuing... Jul 22 02:36:02 DEBUG[11595] channel.c: Nobody there, continuing... Jul 22 02:36:02 DEBUG[11595] channel.c: Nobody there, continuing... ... sending a "stop now" to asterisk: Jul 22 09:24:31 DEBUG[11595] channel.c: Didn't get a frame from channel: SIP/217.111.25.154-08201fe8 Jul 22 09:24:31 DEBUG[11595] channel.c: Bridge stops bridging channels SIP/mysipid-08215dc8 and SIP/217.111.25.154-08201fe8 Jul 22 09:24:31 DEBUG[11595] chan_sip.c: update_call_counter(700554333296999) - decrement call limit counter between this call and the stop now command noone could do any calls. By: Serge Vecher (serge-v) 2006-07-24 08:21:14 please replace the AGI dialing script with a generic Dial() diaplan command for dialing and reproduce. We need to isolate the problem to either an AGI script\subsystem or another core component. Thanks. By: chrisde (chrisde) 2006-07-24 09:45:33 we cannot do this since our billing is based on AGI. The (php)AGI-script does the following: ... $myres = $agi->exec("EXEC DIAL $dialstr"); and one line later: $answeredtime = $agi->get_var("ANSWEREDTIME"); ... so everything between is from Asterisk and shouldn't have anything to do with AGI. If you look at the first debug, only "Jul 15 16:52:51 VERBOSE[18440] logger.c: newalepo.php: >> EXEC DIAL sip/70092215616237 at 217.111.25.154" should be caused by the AGI script. Anything else after this and before the line "Jul 15 18:05:45 VERBOSE[18440] logger.c: newalepo.php: >> GET VARIABLE ANSWEREDTIME" looks like internal channel handling from asterisk, because in the agi script there is also nothing in between. By: chrisde (chrisde) 2006-07-25 07:30:58 very strange: show channels Channel Location State Application(Data) SIP/mysipid-0827 34952928103@from-gig Ring Dial(SIP/20034952928103@66.241 ... 10 active channels 7 active calls show channel SIP/mysipid-0827 server*CLI> show channel SIP/mysipid-0827 SIP/mysipid-0827 is not a known channel sip1-ffm*CLI> sip show channels Peer User/ANR Call ID Seq (Tx/Rx) Form Hold Last Message 192.168.1.2 (None) KZUrMUhT6R6 00101/07582 unkn No Rx: REGISTER 192.168.123.175 (None) 2f71f501540 00101/32207 unkn No Rx: REGISTER 195.137.50.130 (None) 0b138b7f72a 00101/10565 unkn No Rx: REGISTER 213.149.247.73 (None) 4bc444631b7 00101/00229 unkn No Rx: REGISTER 217.111.25.154 7005548364 30e22e9b534 00102/00000 ulaw No Tx: ACK 66.241.7.200 2005551347 6af9da1a52a 00102/00000 g729 No Tx: ACK 0.0.0.0 (None) 00f5d19e19f 00101/00000 unkn No 0.0.0.0 (None) 4e1e01087f8 00101/00000 unkn No 0.0.0.0 (None) 6d3c21b91b4 00101/00000 unkn No 192.168.2.59 mysipid 1102520504@ 00101/00021 g729 No Rx: ACK 0.0.0.0 (None) 6ac2ecf51c2 00101/00000 unkn No ... ... 0.0.0.0 (None) 1f89ef10529 00101/00000 unkn No 22 active SIP channels server*CLI> sip show channel 1102520504@ Direction: Incoming Call-ID: 1102520504@192.168.2.59 Our Codec Capability: 270 Non-Codec Capability: 0 Their Codec Capability: 256 Joint Codec Capability: 256 Format g729 Theoretical Address: 192.168.2.59:5064 Received Address: 81.44.158.181:5064 NAT Support: Always Audio IP: 193.47.84.4 (local) Our Tag: as61f80030 Their Tag: 991783329 SIP User agent: GL221SCF-1.36f Username: mysipid Peername: mysipid Original uri: sip:mysipid@192.168.2.59:5064 Caller-ID: mysipid Need Destroy: 0 Last Message: Rx: ACK Promiscuous Redir: No Route: sip:mysipid@192.168.2.59:5064 DTMF Mode: rfc2833 SIP Options: (none) By: Serge Vecher (serge-v) 2006-08-01 08:12:49 chrisDE: this issue may be related to a recently fixed bug ASTERISK-7262. Can you please test revision >= 38611 of 1.2 branch and see if that fixes your issue as well? By: chrisde (chrisde) 2006-08-09 02:37:38 At this time the error doesn't appear anymore. We used the nagios plugin to monitor the asterisk system and its open channels. Now, after disabling nagios the error doesn't appear anymore. I now try to find out what caused the problem, because as I understand everything nagios does is to "show channels" in the manager console.? By: Serge Vecher (serge-v) 2006-08-09 09:20:46 alright, at this point I will close the issue and mark it as caused by third-party software. Feel free to investigate this further and if you do establish that there is a *bug* in Asterisk, feel free to reopen the issue. To avoid any more negative 'karmage', please run your findings by somebody on #asterisk or #asterisk-bugs before reopening. Danke. | ||