Thanks for all the help, but I still can't find what's wrong. I enabled console => notice,warning,error,debug,dtmf like Miguel suggested. The output is attached.
I noticed that the rtp.c session never starts, which as I understand is what catches the dtmf tone, but I could not find how to start it :s. The Answer() and waitExten(5,m) didn't fix my problem. I hope someone can help me see the problem after looking at the attached console output. On Thu, Aug 19, 2010 at 2:46 PM, Danny Nicholas <da...@debsinc.com> wrote: > *From:* asterisk-users-boun...@lists.digium.com [mailto: > asterisk-users-boun...@lists.digium.com] *On Behalf Of *Miguel Molina > *Subject:* Re: [asterisk-users] WaitExten() always times out > > > > <snip> > > Til gave you the answer; When you call out the other end controls timing. > Put a waitexten(5,m) in front of background(welcome) and see if that helps > > > > > -- > _____________________________________________________________________ > -- Bandwidth and Colocation Provided by http://www.api-digital.com -- > New to Asterisk? Join us for a live introductory webinar every Thurs: > http://www.asterisk.org/hello > > asterisk-users mailing list > To UNSUBSCRIBE or update options visit: > http://lists.digium.com/mailman/listinfo/asterisk-users >
-- Executing [...@default:1] Answer("SIP/xx.xx.xxx.xx-00000026", "") in new stack [Aug 20 16:50:04] DEBUG[5319]: chan_sip.c:6197 sip_answer: SIP answering channel: SIP/xx.xx.xxx.xx-00000026 [Aug 20 16:50:04] DEBUG[5319]: chan_sip.c:10426 transmit_response_with_sdp: Setting framing from config on incoming call [Aug 20 16:50:04] DEBUG[5319]: chan_sip.c:10115 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Aug 20 16:50:04] DEBUG[5319]: chan_sip.c:10116 add_sdp: ** Our prefcodec: 0x0 (nothing) [Aug 20 16:50:04] DEBUG[5319]: chan_sip.c:10227 add_sdp: -- Done with adding codecs to SDP [Aug 20 16:50:04] DEBUG[5319]: channel.c:3096 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Aug 20 16:50:04] DEBUG[5319]: chan_sip.c:10363 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Aug 20 16:50:04] DEBUG[5319]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xxx.xx:5060 [Aug 20 16:50:04] DEBUG[1188]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - xx.xx.xxx.xx [Aug 20 16:50:04] DEBUG[1188]: chan_sip.c:23000 sip_devicestate: Checking device state for peer xx.xx.xxx.xx [Aug 20 16:50:04] DEBUG[1188]: devicestate.c:460 do_state_change: Changing state for SIP/xx.xx.xxx.xx - state 2 (In use) [Aug 20 16:50:04] DEBUG[1188]: devicestate.c:440 devstate_event: device 'SIP/xx.xx.xxx.xx' state '2' [Aug 20 16:50:04] DEBUG[1188]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - xx.xx.xxx.xx [Aug 20 16:50:04] DEBUG[1188]: chan_sip.c:23000 sip_devicestate: Checking device state for peer xx.xx.xxx.xx [Aug 20 16:50:04] DEBUG[1188]: devicestate.c:460 do_state_change: Changing state for SIP/xx.xx.xxx.xx - state 2 (In use) [Aug 20 16:50:04] DEBUG[1188]: devicestate.c:440 devstate_event: device 'SIP/xx.xx.xxx.xx' state '2' [Aug 20 16:50:04] DEBUG[1251]: app_queue.c:1084 handle_statechange: Device 'SIP/xx.xx.xxx.xx' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 20 16:50:04] DEBUG[1251]: app_queue.c:1084 handle_statechange: Device 'SIP/xx.xx.xxx.xx' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 20 16:50:04] DEBUG[5319]: channel.c:1882 __ast_answer: Didn't receive a media frame from SIP/xx.xx.xxx.xx-00000026 within 500 ms of answering. Continuing anyway [Aug 20 16:50:04] DEBUG[5319]: pbx.c:3692 pbx_extension_helper: Launching 'WaitExten' -- Executing [...@default:2] WaitExten("SIP/xx.xx.xxx.xx-00000026", "10,m") in new stack -- Started music on hold, class 'default', on SIP/xx.xx.xxx.xx-00000026 [Aug 20 16:50:04] DEBUG[5319]: channel.c:2426 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Aug 20 16:50:04] DEBUG[5319]: channel.c:3727 set_format: Set channel SIP/xx.xx.xxx.xx-00000026 to write format slin [Aug 20 16:50:04] DEBUG[5319]: res_musiconhold.c:303 ast_moh_files_next: SIP/xx.xx.xxx.xx-00000026 Opened file 1 '/var/lib/asterisk/moh/manolo_camp-morning_coffee' [Aug 20 16:50:04] DEBUG[5319]: rtp.c:3832 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 20 16:50:04] DEBUG[5319]: rtp.c:3858 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Aug 20 16:50:05] DEBUG[1232]: chan_sip.c:3758 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #6725)) [Aug 20 16:50:05] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xxx.xx:5060 [Aug 20 16:50:06] DEBUG[1232]: chan_sip.c:3758 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #6725)) [Aug 20 16:50:06] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xxx.xx:5060 [Aug 20 16:50:06] DEBUG[1232]: chan_sip.c:21639 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 20 16:50:06] DEBUG[1232]: chan_sip.c:21658 handle_incoming: Ignoring SIP message because of retransmit (REGISTER Seqno 437, ours 437) [Aug 20 16:50:06] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for xx.xx.xxx.xxx:5060 [Aug 20 16:50:08] DEBUG[1232]: chan_sip.c:3758 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #6725)) [Aug 20 16:50:08] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xxx.xx:5060 [Aug 20 16:50:10] DEBUG[1232]: chan_sip.c:21639 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 20 16:50:10] DEBUG[1232]: chan_sip.c:21658 handle_incoming: Ignoring SIP message because of retransmit (REGISTER Seqno 437, ours 437) [Aug 20 16:50:10] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for xx.xx.xxx.xxx:5060 [Aug 20 16:50:12] DEBUG[1232]: chan_sip.c:3758 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #6725)) [Aug 20 16:50:12] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xxx.xx:5060 [Aug 20 16:50:14] DEBUG[1232]: chan_sip.c:21639 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 20 16:50:14] DEBUG[1232]: chan_sip.c:21658 handle_incoming: Ignoring SIP message because of retransmit (REGISTER Seqno 437, ours 437) [Aug 20 16:50:14] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for xx.xx.xxx.xxx:5060 -- Timeout on SIP/xx.xx.xxx.xx-00000026, continuing... -- Stopped music on hold on SIP/xx.xx.xxx.xx-00000026 [Aug 20 16:50:15] DEBUG[5319]: channel.c:3727 set_format: Set channel SIP/xx.xx.xxx.xx-00000026 to write format ulaw [Aug 20 16:50:15] DEBUG[5319]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Aug 20 16:50:15] DEBUG[5319]: pbx.c:3692 pbx_extension_helper: Launching 'BackGround' -- Executing [...@default:3] BackGround("SIP/xx.xx.xxx.xx-00000026", "welcome") in new stack [Aug 20 16:50:15] DEBUG[5319]: channel.c:3727 set_format: Set channel SIP/xx.xx.xxx.xx-00000026 to write format slin [Aug 20 16:50:15] DEBUG[5319]: channel.c:2426 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- <SIP/xx.xx.xxx.xx-00000026> Playing 'welcome.slin' (language 'en') [Aug 20 16:50:15] DEBUG[1232]: chan_sip.c:7290 sip_alloc: Allocating new SIP dialog for 05ebb38b28f469701c23d6da56d16...@xx.xx.xxx.xxx - OPTIONS (No RTP) [Aug 20 16:50:15] DEBUG[1232]: acl.c:506 ast_ouraddrfor: Found IP address for this socket [Aug 20 16:50:15] DEBUG[1232]: chan_sip.c:3ext ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address xx.xx.xxx.xxx:5060 [Aug 20 16:50:15] DEBUG[1232]: chan_sip.c:3271 initialize_initreq: Initializing initreq for method OPTIONS - callid 3df854ad23e4f76428e933c1191ac...@xx.xx.xxx.xxx [Aug 20 16:50:15] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for xx.xx.xxx.xxx:5060 [Aug 20 16:50:15] DEBUG[1232]: chan_sip.c:4093 __sip_ack: Stopping retransmission on '3df854ad23e4f76428e933c1191ac...@xx.xx.xxx.xxx' of Request 102: Match Found [Aug 20 16:50:15] DEBUG[1232]: chan_sip.c:5788 sip_destroy: Destroying SIP dialog 3df854ad23e4f76428e933c1191ac...@xx.xx.xxx.xxx [Aug 20 16:50:16] DEBUG[1232]: chan_sip.c:3758 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #6725)) [Aug 20 16:50:16] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xxx.xx:5060 [Aug 20 16:50:18] DEBUG[1232]: chan_sip.c:21639 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 20 16:50:18] DEBUG[1232]: chan_sip.c:21658 handle_incoming: Ignoring SIP message because of retransmit (REGISTER Seqno 437, ours 437) [Aug 20 16:50:18] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for xx.xx.xxx.xxx:5060 [Aug 20 16:50:19] DEBUG[5319]: channel.c:2426 ast_settimeout: Scheduling timer at (216 requested / 100 actual) timer ticks per second [Aug 20 16:50:19] DEBUG[5319]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Aug 20 16:50:19] DEBUG[5319]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Aug 20 16:50:19] DEBUG[5319]: channel.c:2426 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Aug 20 16:50:19] DEBUG[5319]: channel.c:3727 set_format: Set channel SIP/xx.xx.xxx.xx-00000026 to write format ulaw [Aug 20 16:50:19] DEBUG[5319]: pbx.c:3692 pbx_extension_helper: Launching 'WaitExten' -- Executing [...@default:4] WaitExten("SIP/xx.xx.xxx.xx-00000026", "7") in new stack [Aug 20 16:50:20] DEBUG[1232]: chan_sip.c:3758 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #6725)) [Aug 20 16:50:20] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xxx.xx:5060 [Aug 20 16:50:22] DEBUG[1232]: chan_sip.c:21639 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 20 16:50:22] DEBUG[1232]: chan_sip.c:21658 handle_incoming: Ignoring SIP message because of retransmit (REGISTER Seqno 437, ours 437) [Aug 20 16:50:22] DEBUG[1232]: chan_sip.c:3557 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for xx.xx.xxx.xxx:5060 [Aug 20 16:50:24] WARNING[1232]: chan_sip.c:3780 retrans_pkt: Maximum retries exceeded on transmission 233c05aa3addf5dc0d4947bb653a5...@xx.xx.xxx.xx for seqno 102 (Critical Response) -- See doc/sip-retransmit.txt. [Aug 20 16:50:24] DEBUG[1232]: chan_sip.c:3282 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 233c05aa3addf5dc0d4947bb653a5...@xx.xx.xxx.xx [Aug 20 16:50:24] WARNING[1232]: chan_sip.c:3807 retrans_pkt: Hanging up call 233c05aa3addf5dc0d4947bb653a5...@xx.xx.xxx.xx - no reply to our critical packet (see doc/sip-retransmit.txt).
-- _____________________________________________________________________ -- Bandwidth and Colocation Provided by http://www.api-digital.com -- New to Asterisk? Join us for a live introductory webinar every Thurs: http://www.asterisk.org/hello asterisk-users mailing list To UNSUBSCRIBE or update options visit: http://lists.digium.com/mailman/listinfo/asterisk-users