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 '[EMAIL PROTECTED]' 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 '[EMAIL PROTECTED]' 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 '[EMAIL PROTECTED]' Request 102: Found Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission (but retaining packet) on '[EMAIL PROTECTED]' Request 102: Found Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission (but retaining packet) on '[EMAIL PROTECTED]' 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 '[EMAIL PROTECTED]' 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 '[EMAIL PROTECTED]' 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 '[EMAIL PROTECTED]' of Request 102: Found Jan 12 19:38:49 DEBUG[1546]: Stopping retransmission on '[EMAIL PROTECTED]' 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 '[EMAIL PROTECTED]' 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 **************************** _______________________________________________ --Bandwidth and Colocation provided by Easynews.com -- Asterisk-Users mailing list To UNSUBSCRIBE or update options visit: http://lists.digium.com/mailman/listinfo/asterisk-users