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@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@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@192.168.1.200' Request 102: Found
Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission
(but retaining packet) on
'4f8cfbeb6939edf431465dbe780d7d69@192.168.1.200' Request 102: Found
Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission
(but retaining packet) on
'66656f196342cc765ba57344169430de@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@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@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@192.168.1.200' of Request 102: Found
Jan 12 19:38:49 DEBUG[1546]: Stopping retransmission on
'4f8cfbeb6939edf431465dbe780d7d69@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@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
****************************
I have this exact same problem, so far I have not been able to figure out whats going on. I also get the follwoing errors: =====Didn't get a frame from channel: SIP/119-41c6 Bridge stops bridging channels SIP/119-41c6 and SIP/101-264e =====Which tells us that a frame was dropped. Lets try compring setups: 1. What phones are you using? 2. Is asterisk in the media path? 3. Are they all local without NAT? 4. What phone is SIP/101? 5. What phone is SIP/119? 6. What platform is Asterisk running on (Intel? AMD? etc.)? 7. What switch are you using? 8. What version of Asterisk are you running? On 1/12/06, Thczv F. Thczv <thczv.thczv@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@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@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@192.168.1.200' Request 102: Found > Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission > (but retaining packet) on > '4f8cfbeb6939edf431465dbe780d7d69@192.168.1.200' Request 102: Found > Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission > (but retaining packet) on > '66656f196342cc765ba57344169430de@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@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@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@192.168.1.200' of Request 102: Found > Jan 12 19:38:49 DEBUG[1546]: Stopping retransmission on > '4f8cfbeb6939edf431465dbe780d7d69@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@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 > **************************** > _______________________________________________ > --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 >
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@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@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@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@192.168.1.200' Request 102: Found > Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission > (but retaining packet) on > '4f8cfbeb6939edf431465dbe780d7d69@192.168.1.200' Request 102: Found > Jan 12 19:38:44 DEBUG[1546]: (Provisional) Stopping retransmission > (but retaining packet) on > '66656f196342cc765ba57344169430de@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@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@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@192.168.1.200' of Request 102: Found > Jan 12 19:38:49 DEBUG[1546]: Stopping retransmission on > '4f8cfbeb6939edf431465dbe780d7d69@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@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 > **************************** >