[Asterisk-Users] Unprovoked hangups

Wed Aug 31 14:36:59 MST 2005

Hi!
 We have a SIP server with a TE410P card with asterisk version Asterisk 
CVS-D2005.02.12.14.37.11-04/13/05-16:14:03. Sometime the calls get 
disconnected with now reason and the users get a busy signal. The log file 
show this for one of the calls that got disconnected:
 Aug 31 22:51:53 VERBOSE[3911]: -- Accepting call from '46362302' to 
'36917474' on channel 0/5, span 1
Aug 31 22:51:53 DEBUG[3911]: Enabled echo cancellation on channel 5
Aug 31 22:51:53 VERBOSE[21799]: -- Executing 
ESC[1;36;40mMacroESC[0;37;40m("ESC[1;35;40mZap/5-1ESC[0;37;40m", 
"ESC[1;35;40mstdexten|079999|SIP/079999ESC[0;37;40m")
Aug 31 22:51:53 VERBOSE[21799]: -- Executing 
ESC[1;36;40mDBgetESC[0;37;40m("ESC[1;35;40mZap/5-1ESC[0;37;40m", 
"ESC[1;35;40mtemp=CFIM/079999ESC[0;37;40m") in new stack
Aug 31 22:51:53 VERBOSE[21799]: -- DBget: varname=temp, family=CFIM, 
key=079999
Aug 31 22:51:53 DEBUG[21799]: Unable to find key '079999' in family 'CFIM'
Aug 31 22:51:53 VERBOSE[21799]: -- DBget: Value not found in database.
Aug 31 22:51:53 VERBOSE[21799]: -- Executing 
ESC[1;36;40mGotoESC[0;37;40m("ESC[1;35;40mZap/5-1ESC[0;37;40m", 
"ESC[1;35;40ms|11ESC[0;37;40m") in new stack
Aug 31 22:51:53 VERBOSE[21799]: -- Goto (macro-stdexten,s,11)
Aug 31 22:51:53 VERBOSE[21799]: -- Executing 
ESC[1;36;40mDialESC[0;37;40m("ESC[1;35;40mZap/5-1ESC[0;37;40m", 
"ESC[1;35;40mSIP/079999|40ESC[0;37;40m") in new stack
Aug 31 22:51:53 VERBOSE[21799]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:51:53 DEBUG[21799]: Setting NAT on RTP to 524288
Aug 31 22:51:53 DEBUG[21799]: Outgoing Call for 36917474
Aug 31 22:51:53 DEBUG[21799]: 36917474 is not a local user
Aug 31 22:51:53 VERBOSE[21799]: -- Called 079999
Aug 31 22:51:53 DEBUG[3916]: (Provisional) Stopping retransmission (but 
retaining packet) on
'07640a664ced6ffa7006f3916dac5cc2 at 194.255.106.3'Request 102: Found
Aug 31 22:51:53 DEBUG[3916]: Acked pending invite 102
Aug 31 22:51:53 DEBUG[3916]: Stopping retransmission on 
'07640a664ced6ffa7006f3916dac5cc2 at 194.255.106.3' of Request 102: Found
Aug 31 22:51:53 DEBUG[3916]: build_route: Contact hop: <
sip:36917474 at 83.95.111.21>
Aug 31 22:51:53 VERBOSE[21799]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:51:53 VERBOSE[21799]: -- SIP/079999-8a0b answered Zap/5-1
Aug 31 22:51:53 DEBUG[21799]: RTP NAT: Using address
83.95.111.21:22138<http://83.95.111.21:22138>
Aug 31 22:51:53 DEBUG[21799]: Oooh, format changed to 2
Aug 31 22:52:59 VERBOSE[3916]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:52:59 VERBOSE[3916]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:52:59 VERBOSE[3916]: -- Saved useragent "Asterisk PBX" for peer 
079999
Aug 31 22:52:59 VERBOSE[3916]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:53:14 DEBUG[3916]: Auto destroying call 
'46d329fd2fc9a5763c3ffb184ef755f1 at 127.0.0.1'
Aug 31 22:55:01 DEBUG[21806]: Manager received command 'Login'
Aug 31 22:55:01 VERBOSE[21806]: == Parsing '/etc/asterisk/manager.conf': Aug 
31 22:55:01 VERBOSE[21806]: == Parsing '/etc/asterisk/manager.conf': Found
Aug 31 22:55:01 DEBUG[21806]:
0.0.0.0/0.0.0.0/0.0.0.0<http://0.0.0.0/0.0.0.0/0.0.0.0>appended to acl
for peer
Aug 31 22:55:01 DEBUG[21806]:
127.0.0.1/255.255.255.0/255.255.255.0<http://127.0.0.1/255.255.255.0/255.255.255.0>appended
to acl for peer
Aug 31 22:55:01 DEBUG[21806]: ##### Testing 127.0.0.1 <http://127.0.0.1>with 
0.0.0.0 <http://0.0.0.0>
Aug 31 22:55:01 DEBUG[21806]: ##### Testing 127.0.0.1 <http://127.0.0.1>with 
127.0.0.0 <http://127.0.0.0>
Aug 31 22:55:01 VERBOSE[21806]: == Manager 'admin' logged on from
127.0.0.1<http://127.0.0.1>
Aug 31 22:55:01 DEBUG[21806]: Manager received command 'Ping'
Aug 31 22:55:01 DEBUG[21806]: Manager received command 'Logoff'
Aug 31 22:55:01 VERBOSE[21806]: == Manager 'admin' logged off from
127.0.0.1<http://127.0.0.1>
Aug 31 22:55:01 DEBUG[21823]: Manager received command 'Login'
Aug 31 22:55:01 VERBOSE[21823]: == Parsing '/etc/asterisk/manager.conf': Aug 
31 22:55:01 VERBOSE[21823]: == Parsing '/etc/asterisk/manager.conf': Found
Aug 31 22:55:01 DEBUG[21823]:
0.0.0.0/0.0.0.0/0.0.0.0<http://0.0.0.0/0.0.0.0/0.0.0.0>appended to acl
for peer
Aug 31 22:55:01 DEBUG[21823]:
127.0.0.1/255.255.255.0/255.255.255.0<http://127.0.0.1/255.255.255.0/255.255.255.0>appended
to acl for peer
Aug 31 22:55:01 DEBUG[21823]: ##### Testing 127.0.0.1 <http://127.0.0.1>with 
0.0.0.0 <http://0.0.0.0>
Aug 31 22:55:01 DEBUG[21823]: ##### Testing 127.0.0.1 <http://127.0.0.1>with 
127.0.0.0 <http://127.0.0.0>
Aug 31 22:55:01 VERBOSE[21823]: == Manager 'admin' logged on from
127.0.0.1<http://127.0.0.1>
Aug 31 22:55:01 DEBUG[21823]: Manager received command 'Status'
Aug 31 22:55:01 DEBUG[21823]: Manager received command 'Logoff'
Aug 31 22:55:01 VERBOSE[21823]: == Manager 'admin' logged off from
127.0.0.1<http://127.0.0.1>
Aug 31 22:55:24 VERBOSE[3916]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:55:24 VERBOSE[3916]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:55:24 VERBOSE[3916]: -- Saved useragent "Asterisk PBX" for peer 
079999
Aug 31 22:55:24 VERBOSE[3916]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:55:39 DEBUG[3916]: Auto destroying call 
'46d329fd2fc9a5763c3ffb184ef755f1 at 127.0.0.1'
Aug 31 22:57:49 VERBOSE[3916]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:57:49 VERBOSE[3916]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:57:49 VERBOSE[3916]: -- Saved useragent "Asterisk PBX" for peer 
079999
Aug 31 22:57:49 VERBOSE[3916]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:57:49 DEBUG[3916]: Avoiding initial deadlock for 'SIP/079999-8a0b'
Aug 31 22:57:50 VERBOSE[3911]: -- Channel 0/5, span 1 got hangup
Aug 31 22:57:50 DEBUG[21799]: Bridge stops because we're zombie or need a 
soft hangup: c0=Zap/5-1, c1=SIP/079999-8a0b, flags: No,Yes,No,No
Aug 31 22:57:50 DEBUG[21799]: Bridge stops bridging channels Zap/5-1 and 
SIP/079999-8a0b
Aug 31 22:57:50 DEBUG[21799]: update_user_counter(36917474) - decrement 
outUse counter
Aug 31 22:57:50 DEBUG[21799]: 36917474 is not a local user
Aug 31 22:57:50 VERBOSE[21799]: -- SIP Seeding '079999' at 
36917474 at 83.95.111.21:22034 for 160
Aug 31 22:57:50 DEBUG[21799]: Exiting with DIALSTATUS=ANSWER.
Aug 31 22:57:50 VERBOSE[21799]: == Spawn extension (macro-stdexten, s, 11) 
exited non-zero on 'Zap/5-1' in macro 'stdexten'
Aug 31 22:57:50 VERBOSE[21799]: == Spawn extension (isdn30_1, 36917474, 1) 
exited non-zero on 'Zap/5-1'
Aug 31 22:57:50 DEBUG[21799]: Set option AUDIO MODE, value: ON(1) on Zap/5-1
Aug 31 22:57:50 DEBUG[21799]: Hangup: channel: 5 index = 0, normal = 26, 
callwait = -1, thirdcall = -1
Aug 31 22:57:50 DEBUG[21799]: Not yet hungup... Calling hangup once with 
icause, and clearing call
Aug 31 22:57:50 DEBUG[21799]: disabled echo cancellation on channel 5
Aug 31 22:57:50 DEBUG[21799]: Set option TDD MODE, value: OFF(0) on Zap/5-1
Aug 31 22:57:50 DEBUG[21799]: Updated conferencing on 5, with 0 conference 
users
Aug 31 22:57:50 DEBUG[21799]: Set option AUDIO MODE, value: OFF(0) on 
Zap/5-1
Aug 31 22:57:50 DEBUG[21799]: disabled echo cancellation on channel 5
Aug 31 22:57:50 VERBOSE[21799]: -- Hungup 'Zap/5-1'
Aug 31 22:57:50 DEBUG[3916]: Stopping retransmission on 
'07640a664ced6ffa7006f3916dac5cc2 at 194.255.106.3' of Request 103: Found
 Can someone explain what happend?
 How can we fix this problem. Will it help to upgrade to asterisk 1.0.9? Or 
upgrade the firmware on the TE410P card?
 
-- 
Morten Isaksen
http://www.misak.dk/blog/
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-users/attachments/20050831/029990ef/attachment.htm