[asterisk-users] WaitExten() always times out

Fri Aug 20 16:14:09 CDT 2010

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 <danny at debsinc.com> wrote:

>   *From:* asterisk-users-bounces at lists.digium.com [mailto:
> asterisk-users-bounces at 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-users/attachments/20100820/bfe6835b/attachment.htm 
-------------- next part --------------
    -- Executing [ext at 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 [ext at 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 [ext at 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 05ebb38b28f469701c23d6da56d162b0 at 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 3df854ad23e4f76428e933c1191ac375 at 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 '3df854ad23e4f76428e933c1191ac375 at 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 3df854ad23e4f76428e933c1191ac375 at 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 [ext at 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 233c05aa3addf5dc0d4947bb653a566e at 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 233c05aa3addf5dc0d4947bb653a566e at xx.xx.xxx.xx
[Aug 20 16:50:24] WARNING[1232]: chan_sip.c:3807 retrans_pkt: Hanging up call 233c05aa3addf5dc0d4947bb653a566e at xx.xx.xxx.xx - no reply to our critical packet (see doc/sip-retransmit.txt).