[Asterisk-Users] Random Disconnects

[Thczv F. Thczv]

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
****************************