[Asterisk-Users] Re: Random Disconnects

[Thczv F. Thczv]

I have noticed that several other people have encountered the same
problem.  See here:

http://lists.digium.com/pipermail/asterisk-users/2005-June/114559.html
http://lists.digium.com/pipermail/asterisk-users/2005-June/111534.html
http://voxilla.com/index.php?name=PNphpBB2&file=viewtopic&p=34506

I can't tell whether it is a configuration problem or a bug.

Have any of you run into this problem before?

Thanks,

Dave

On 1/12/06, Thczv F. Thczv <thczv.thczv at gmail.com> wrote:
> I am hoping some of you can help me troubleshoot this problem I am
> having with my home asterisk machine.  I have incoming POTS service
> using a SPA-3000 (extension 119).  Calls on that line go to an
> attendant recording that offers a menu choice: press 1 for Nancy,
> press 2 for the rest of us.  In reality, pressing anything other than
> 1 sends the call to the rest of us by dialing both extensions 101 and
> 109.  Tonight we received a call on this POTS line.  The caller
> pressed 2.  We answered extension 101.  Several seconds later, the
> call was cut off.  However, I noticed that extension 109 started (or
> was still) ringing.  But the caller wasn't completely disconnected.
> He ended up leaving a voicemail message for extension 101 (which is
> where calls to 101 or 109 go).
>
> Any ideas what might be going on here?  I have included logs from this
> call below.
>
> I would appreciate any advice.  This Asterisk hobby of mine is just
> barely passing the wife test.  :-)  I'm not sure how long it will
> last.
>
> Thanks,
>
> Dave
>
> **************
> Jan 12 19:38:36 DEBUG[1546]: Setting NAT on RTP to 0
> Jan 12 19:38:36 DEBUG[1546]: Stopping retransmission on
> '77221494-cabe184e at 192.168.1.150' of Response 101: Found
> Jan 12 19:38:36 DEBUG[1546]: Setting NAT on RTP to 0
> Jan 12 19:38:36 DEBUG[1546]: Check for res for 119
> Jan 12 19:38:36 DEBUG[1546]: Call from user '119' is 1 out of 0
> Jan 12 19:38:36 DEBUG[1546]: build_route: Contact hop: SureWest
> Jan 12 19:38:36 VERBOSE[1546]: -- Executing Goto("SIP/119-41c6",
> "auto-attendant|115|1") in new stack
> Jan 12 19:38:36 VERBOSE[1546]: -- Goto (auto-attendant,115,1)
> Jan 12 19:38:36 VERBOSE[1546]: -- Executing Answer("SIP/119-41c6", "")
> in new stack
> Jan 12 19:38:36 VERBOSE[1546]: -- Executing Wait("SIP/119-41c6", "1")
> in new stack
> Jan 12 19:38:36 DEBUG[1546]: Stopping retransmission on
> '77221494-cabe184e at 192.168.1.150' of Response 102: Found
> Jan 12 19:38:37 VERBOSE[1546]: -- Executing
> ResponseTimeout("SIP/119-41c6", "7") in new stack
> Jan 12 19:38:37 VERBOSE[1546]: -- Set Response Timeout to 7
> Jan 12 19:38:37 VERBOSE[1546]: -- Executing BackGround("SIP/119-41c6",
> "/var/lib/asterisk/sounds/custom/haddock-main-menu") in new stack
> Jan 12 19:38:37 DEBUG[1546]: Ooh, format changed from unknown to ulaw
> Jan 12 19:38:37 DEBUG[1546]: Scheduling timer at 160 sample intervals
> Jan 12 19:38:37 VERBOSE[1546]: -- Playing
> '/var/lib/asterisk/sounds/custom/haddock-main-menu' (language 'en')
> Jan 12 19:38:42 DEBUG[1546]: Scheduling timer at 138 sample intervals
> Jan 12 19:38:42 DEBUG[1546]: Scheduling timer at 0 sample intervals
> Jan 12 19:38:42 DEBUG[1546]: Scheduling timer at 0 sample intervals
> Jan 12 19:38:44 DEBUG[1546]: Sending dtmf: 50 (2), at 192.168.1.150
> Jan 12 19:38:44 VERBOSE[1546]: -- Invalid extension '2' in context
> 'auto-attendant' on SIP/119-41c6
> Jan 12 19:38:44 VERBOSE[1546]: == CDR updated on SIP/119-41c6
> Jan 12 19:38:44 VERBOSE[1546]: -- Executing Goto("SIP/119-41c6",
> "from-pstn|main|1") in new stack
> Jan 12 19:38:44 VERBOSE[1546]: -- Goto (from-pstn,main,1)
> Jan 12 19:38:44 VERBOSE[1546]: -- Executing Dial("SIP/119-41c6",
> "SIP/101&SIP/109|20") in new stack
> Jan 12 19:38:44 DEBUG[1546]: Setting NAT on RTP to 0
> Jan 12 19:38:44 DEBUG[1546]: Outgoing Call for 101
> Jan 12 19:38:44 DEBUG[1546]: Call from user '101' is 1 out of 0
> Jan 12 19:38:44 VERBOSE[1546]: -- Called 101
> Jan 12 19:38:44 DEBUG[1546]: Setting NAT on RTP to 0
> Jan 12 19:38:44 DEBUG[1546]: Outgoing Call for 109
> Jan 12 19:38:44 DEBUG[1546]: Call from user '109' is 1 out of 0
> Jan 12 19:38:44 VERBOSE[1546]: -- Called 109
> Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission
> (but retaining packet) on
> '66656f196342cc765ba57344169430de at 192.168.1.200' Request 102: Found
> Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission
> (but retaining packet) on
> '4f8cfbeb6939edf431465dbe780d7d69 at 192.168.1.200' Request 102: Found
> Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission
> (but retaining packet) on
> '66656f196342cc765ba57344169430de at 192.168.1.200' Request 102: Found
> Jan 12 19:38:44 VERBOSE[1546]: -- SIP/101-264e is ringing
> Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission
> (but retaining packet) on
> '4f8cfbeb6939edf431465dbe780d7d69 at 192.168.1.200' Request 102: Found
> Jan 12 19:38:44 DEBUG[1546]: Driver for channel 'SIP/119-41c6' does
> not support indication 3, emulating it
> Jan 12 19:38:44 DEBUG[1546]: Scheduling timer at 160 sample intervals
> Jan 12 19:38:44 VERBOSE[1546]: -- SIP/109-88dd is ringing
> Jan 12 19:38:44 DEBUG[1546]: Generator got voice, switching to phase locked mode
> Jan 12 19:38:44 DEBUG[1546]: Scheduling timer at 0 sample intervals
> Jan 12 19:38:44 DEBUG[1546]: Difference is 15304, ms is 1933
> Jan 12 19:38:49 DEBUG[1546]: Acked pending invite 102
> Jan 12 19:38:49 DEBUG[1546]: Stopping retransmission on
> '66656f196342cc765ba57344169430de at 192.168.1.200' of Request 102: Found
> Jan 12 19:38:49 DEBUG[1546]: build_route: Contact hop:
> Jan 12 19:38:49 VERBOSE[1546]: -- SIP/101-264e answered SIP/119-41c6
> Jan 12 19:38:49 DEBUG[1546]: update_user_counter(109) - decrement outUse counter
> Jan 12 19:38:49 DEBUG[1546]: Scheduling timer at 0 sample intervals
> Jan 12 19:38:49 VERBOSE[1546]: -- Attempting native bridge of
> SIP/119-41c6 and SIP/101-264e
> Jan 12 19:38:49 DEBUG[1546]: Acked pending invite 102
> Jan 12 19:38:49 DEBUG[1546]: Stopping retransmission on
> '4f8cfbeb6939edf431465dbe780d7d69 at 192.168.1.200' of Request 102: Found
> Jan 12 19:38:49 DEBUG[1546]: Stopping retransmission on
> '4f8cfbeb6939edf431465dbe780d7d69 at 192.168.1.200' of Request 102: Found
> Jan 12 19:38:49 DEBUG[1546]: Ooh, format changed from unknown to ulaw
> Jan 12 19:39:22 DEBUG[1546]: Manager received command 'Command'
> Jan 12 19:39:22 DEBUG[1546]: Manager received command 'Command'
> Jan 12 19:39:30 DEBUG[1546]: Didn't get a frame from channel: SIP/119-41c6
> Jan 12 19:39:30 DEBUG[1546]: Bridge stops bridging channels
> SIP/119-41c6 and SIP/101-264e
> Jan 12 19:39:30 DEBUG[1546]: update_user_counter(101) - decrement outUse counter
> Jan 12 19:39:30 DEBUG[1546]: Exiting with DIALSTATUS=ANSWER.
> Jan 12 19:39:30 VERBOSE[1546]: == Spawn extension (from-pstn, main, 1)
> exited non-zero on 'SIP/119-41c6'
> Jan 12 19:39:30 DEBUG[1546]: Stopping retransmission on
> '66656f196342cc765ba57344169430de at 192.168.1.200' of Request 103: Found
> Jan 12 19:39:30 DEBUG[1546]: cdr_mysql: inserting a CDR record.
> Jan 12 19:39:30 DEBUG[1546]: 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-01-12 19:38:36','\"SureWest\"
> <119>','119','main','from-pstn',
> 'SIP/119-41c6','SIP/101-264e','Dial','SIP/101&SIP/109|20',54,54,'ANSWERED',3,'')
> Jan 12 19:39:31 DEBUG[1546]: update_user_counter(119) - decrement inUse counter
> ****************************
>