<div>Hi!</div>
<div> </div>
<div>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:
</div>
<div> </div>
<div>Aug 31 22:51:53 VERBOSE[3911]: -- Accepting call from '46362302' to '36917474' on channel 0/5, span 1<br>Aug 31 22:51:53 DEBUG[3911]: Enabled echo cancellation on channel 5<br>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")
<br>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<br>Aug 31 22:51:53 VERBOSE[21799]: -- DBget: varname=temp, family=CFIM, key=079999
<br>Aug 31 22:51:53 DEBUG[21799]: Unable to find key '079999' in family 'CFIM'<br>Aug 31 22:51:53 VERBOSE[21799]: -- DBget: Value not found in database.<br>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
<br>Aug 31 22:51:53 VERBOSE[21799]: -- Goto (macro-stdexten,s,11)<br>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
<br>Aug 31 22:51:53 VERBOSE[21799]: -- SIP Seeding '079999' at <a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:51:53 DEBUG[21799]: Setting NAT on RTP to 524288<br>Aug 31 22:51:53 DEBUG[21799]: Outgoing Call for 36917474
<br>Aug 31 22:51:53 DEBUG[21799]: 36917474 is not a local user<br>Aug 31 22:51:53 VERBOSE[21799]: -- Called 079999<br>Aug 31 22:51:53 DEBUG[3916]: (Provisional) Stopping retransmission (but retaining packet) on <a href="mailto:'07640a664ced6ffa7006f3916dac5cc2@194.255.106.3'">
'07640a664ced6ffa7006f3916dac5cc2@194.255.106.3'</a> Request 102: Found<br>Aug 31 22:51:53 DEBUG[3916]: Acked pending invite 102<br>Aug 31 22:51:53 DEBUG[3916]: Stopping retransmission on <a href="mailto:'07640a664ced6ffa7006f3916dac5cc2@194.255.106.3'">
'07640a664ced6ffa7006f3916dac5cc2@194.255.106.3'</a> of Request 102: Found<br>Aug 31 22:51:53 DEBUG[3916]: build_route: Contact hop: <<a href="mailto:sip:36917474@83.95.111.21">sip:36917474@83.95.111.21</a>><br>Aug 31 22:51:53 VERBOSE[21799]: -- SIP Seeding '079999' at
<a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:51:53 VERBOSE[21799]: -- SIP/079999-8a0b answered Zap/5-1<br>Aug 31 22:51:53 DEBUG[21799]: RTP NAT: Using address <a href="http://83.95.111.21:22138">
83.95.111.21:22138</a><br>Aug 31 22:51:53 DEBUG[21799]: Oooh, format changed to 2<br>Aug 31 22:52:59 VERBOSE[3916]: -- SIP Seeding '079999' at <a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a>
for 160<br>Aug 31 22:52:59 VERBOSE[3916]: -- SIP Seeding '079999' at <a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:52:59 VERBOSE[3916]: -- Saved useragent "Asterisk PBX" for peer 079999
<br>Aug 31 22:52:59 VERBOSE[3916]: -- SIP Seeding '079999' at <a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:53:14 DEBUG[3916]: Auto destroying call <a href="mailto:'46d329fd2fc9a5763c3ffb184ef755f1@127.0.0.1'">
'46d329fd2fc9a5763c3ffb184ef755f1@127.0.0.1'</a><br>Aug 31 22:55:01 DEBUG[21806]: Manager received command 'Login'<br>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
<br>Aug 31 22:55:01 DEBUG[21806]: <a href="http://0.0.0.0/0.0.0.0/0.0.0.0">0.0.0.0/0.0.0.0/0.0.0.0</a> appended to acl for peer<br>Aug 31 22:55:01 DEBUG[21806]: <a href="http://127.0.0.1/255.255.255.0/255.255.255.0">127.0.0.1/255.255.255.0/255.255.255.0
</a> appended to acl for peer<br>Aug 31 22:55:01 DEBUG[21806]: ##### Testing <a href="http://127.0.0.1">127.0.0.1</a> with <a href="http://0.0.0.0">0.0.0.0</a><br>Aug 31 22:55:01 DEBUG[21806]: ##### Testing <a href="http://127.0.0.1">
127.0.0.1</a> with <a href="http://127.0.0.0">127.0.0.0</a><br>Aug 31 22:55:01 VERBOSE[21806]: == Manager 'admin' logged on from <a href="http://127.0.0.1">127.0.0.1</a><br>Aug 31 22:55:01 DEBUG[21806]: Manager received command 'Ping'
<br>Aug 31 22:55:01 DEBUG[21806]: Manager received command 'Logoff'<br>Aug 31 22:55:01 VERBOSE[21806]: == Manager 'admin' logged off from <a href="http://127.0.0.1">127.0.0.1</a><br>Aug 31 22:55:01 DEBUG[21823]: Manager received command 'Login'
<br>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<br>Aug 31 22:55:01 DEBUG[21823]: <a href="http://0.0.0.0/0.0.0.0/0.0.0.0">
0.0.0.0/0.0.0.0/0.0.0.0</a> appended to acl for peer<br>Aug 31 22:55:01 DEBUG[21823]: <a href="http://127.0.0.1/255.255.255.0/255.255.255.0">127.0.0.1/255.255.255.0/255.255.255.0</a> appended to acl for peer<br>Aug 31 22:55:01 DEBUG[21823]: ##### Testing
<a href="http://127.0.0.1">127.0.0.1</a> with <a href="http://0.0.0.0">0.0.0.0</a><br>Aug 31 22:55:01 DEBUG[21823]: ##### Testing <a href="http://127.0.0.1">127.0.0.1</a> with <a href="http://127.0.0.0">127.0.0.0</a><br>Aug 31 22:55:01 VERBOSE[21823]: == Manager 'admin' logged on from
<a href="http://127.0.0.1">127.0.0.1</a><br>Aug 31 22:55:01 DEBUG[21823]: Manager received command 'Status'<br>Aug 31 22:55:01 DEBUG[21823]: Manager received command 'Logoff'<br>Aug 31 22:55:01 VERBOSE[21823]: == Manager 'admin' logged off from
<a href="http://127.0.0.1">127.0.0.1</a><br>Aug 31 22:55:24 VERBOSE[3916]: -- SIP Seeding '079999' at <a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:55:24 VERBOSE[3916]: -- SIP Seeding '079999' at
<a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:55:24 VERBOSE[3916]: -- Saved useragent "Asterisk PBX" for peer 079999<br>Aug 31 22:55:24 VERBOSE[3916]: -- SIP Seeding '079999' at
<a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:55:39 DEBUG[3916]: Auto destroying call <a href="mailto:'46d329fd2fc9a5763c3ffb184ef755f1@127.0.0.1'">'46d329fd2fc9a5763c3ffb184ef755f1@127.0.0.1'
</a><br>Aug 31 22:57:49 VERBOSE[3916]: -- SIP Seeding '079999' at <a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:57:49 VERBOSE[3916]: -- SIP Seeding '079999' at <a href="mailto:36917474@83.95.111.21:22034">
36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:57:49 VERBOSE[3916]: -- Saved useragent "Asterisk PBX" for peer 079999<br>Aug 31 22:57:49 VERBOSE[3916]: -- SIP Seeding '079999' at <a href="mailto:36917474@83.95.111.21:22034">
36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:57:49 DEBUG[3916]: Avoiding initial deadlock for 'SIP/079999-8a0b'<br>Aug 31 22:57:50 VERBOSE[3911]: -- Channel 0/5, span 1 got hangup<br>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
<br>Aug 31 22:57:50 DEBUG[21799]: Bridge stops bridging channels Zap/5-1 and SIP/079999-8a0b<br>Aug 31 22:57:50 DEBUG[21799]: update_user_counter(36917474) - decrement outUse counter<br>Aug 31 22:57:50 DEBUG[21799]: 36917474 is not a local user
<br>Aug 31 22:57:50 VERBOSE[21799]: -- SIP Seeding '079999' at <a href="mailto:36917474@83.95.111.21:22034">36917474@83.95.111.21:22034</a> for 160<br>Aug 31 22:57:50 DEBUG[21799]: Exiting with DIALSTATUS=ANSWER.<br>Aug 31 22:57:50 VERBOSE[21799]: == Spawn extension (macro-stdexten, s, 11) exited non-zero on 'Zap/5-1' in macro 'stdexten'
<br>Aug 31 22:57:50 VERBOSE[21799]: == Spawn extension (isdn30_1, 36917474, 1) exited non-zero on 'Zap/5-1'<br>Aug 31 22:57:50 DEBUG[21799]: Set option AUDIO MODE, value: ON(1) on Zap/5-1<br>Aug 31 22:57:50 DEBUG[21799]: Hangup: channel: 5 index = 0, normal = 26, callwait = -1, thirdcall = -1
<br>Aug 31 22:57:50 DEBUG[21799]: Not yet hungup... Calling hangup once with icause, and clearing call<br>Aug 31 22:57:50 DEBUG[21799]: disabled echo cancellation on channel 5<br>Aug 31 22:57:50 DEBUG[21799]: Set option TDD MODE, value: OFF(0) on Zap/5-1
<br>Aug 31 22:57:50 DEBUG[21799]: Updated conferencing on 5, with 0 conference users<br>Aug 31 22:57:50 DEBUG[21799]: Set option AUDIO MODE, value: OFF(0) on Zap/5-1<br>Aug 31 22:57:50 DEBUG[21799]: disabled echo cancellation on channel 5
<br>Aug 31 22:57:50 VERBOSE[21799]: -- Hungup 'Zap/5-1'<br>Aug 31 22:57:50 DEBUG[3916]: Stopping retransmission on <a href="mailto:'07640a664ced6ffa7006f3916dac5cc2@194.255.106.3'">'07640a664ced6ffa7006f3916dac5cc2@194.255.106.3'
</a> of Request 103: Found</div>
<div> </div>
<div>Can someone explain what happend?</div>
<div> </div>
<div>How can we fix this problem. Will it help to upgrade to asterisk 1.0.9? Or upgrade the firmware on the TE410P card?</div>
<div> </div>
<div><br>-- <br>Morten Isaksen<br><a href="http://www.misak.dk/blog/">http://www.misak.dk/blog/</a> </div>