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

Reply via email to