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 <[email protected]> wrote:
> *From:* [email protected] [mailto:
> [email protected]] *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 [email protected] - 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
[email protected]
[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 '[email protected]' of Request
102: Match Found
[Aug 20 16:50:15] DEBUG[1232]: chan_sip.c:5788 sip_destroy: Destroying SIP
dialog [email protected]
[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 [email protected] 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 [email protected]
[Aug 20 16:50:24] WARNING[1232]: chan_sip.c:3807 retrans_pkt: Hanging up call
[email protected] - 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
