RingBack of Dial cmd after PlayBack cmd, 1.6

simburelu · November 13, 2008, 11:55am

Hi,
H232peer->Asterisk->SIPpeer

The problem is that the caller can not hear a ringback tones after the Dial cmd was executed, if the previouse command was a PlayBack.

Ringback does work for this case:
Wait(1)
Dial(SIP/xxxx@yyyy)

Ringback does NOT work for this case:
Wait(1)
Answer()
Dial(SIP/xxxx@yyyy)

or not work for:

Wait(1)
PlayBack(asd)
Dial(SIP/xxxx@yyyy)

or not work for:

Wait(1)
PlayBack(asd)
Ringing()
Dial(SIP/xxxx@yyyy)

or not work for:

Wait(1)
Answer()
PlayBack(asd)
Dial(SIP/xxxx@yyyy,60,r)

MusicOn hold is not working if the incomming call is received via SIP peer:
Wait(1)
Answer()
MusicOnHold()

or not work for:
Wait(1)
Answer()
Dial(SIP/xxxx@yyyy,60,m)

MusicOnHold do work in case if the call is received via ooH323 peer (so the moh file are in place)
Wait(1)
Answer()
MusicOnHold()

Finaly:
I can not user neither RingBack tone (if the priviouse command was playback or answer) , neither MusicOnHold, if the call is received via Sip peer. But I can hear the playback sound in any of these cases.

By RingBack i mean that the calling part should hear the ring tone until the called party was answered to the call.

The thing is that i have to play something before to place a new call to the destination using Dial cmd.

Thanks!

simburelu · November 14, 2008, 8:56am

.w

david55 · November 14, 2008, 11:29am

Relevant traces.

simburelu · November 15, 2008, 5:29pm

exten => 333222,1,Wait(1)
exten => 333222,2,Answer
exten => 333222,n,Background(intro)
exten => 333222,n,MusicOnHold(default,10)
exten => 333222,n,Background(intro)
exten => 333222,n,Hangup()

Note: MusicOnHold is not played…
all background are played
…

[Nov 15 19:23:58] DEBUG[16630]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82305c0'
[Nov 15 19:23:58] DEBUG[16630]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82305c0'
[Nov 15 19:23:58] DEBUG[16630]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82305c0'
[Nov 15 19:23:58] DEBUG[16630]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82305c0'
[Nov 15 19:23:58] DEBUG[16630]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82305c0'
[Nov 15 19:23:58] DEBUG[16630]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82305c0'
[Nov 15 19:23:58] DEBUG[16630]: devicestate.c:441 do_state_change: Changing state for SIP/333222 - state 2 (In use)
[Nov 15 19:23:58] DEBUG[16642]: app_queue.c:763 handle_statechange: Device 'SIP/333222' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 15 19:23:59] DEBUG[16656]: pbx.c:3094 pbx_extension_helper: Launching 'Answer'
    -- Executing [333222@maximash:2] Answer("SIP/333222-0823fdb8", "") in new stack
[Nov 15 19:23:59] DEBUG[16656]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/333222
[Nov 15 19:23:59] DEBUG[16656]: chan_sip.c:4960 sip_answer: SIP answering channel: SIP/333222-0823fdb8
[Nov 15 19:23:59] DEBUG[16656]: chan_sip.c:8418 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 19:23:59] DEBUG[16656]: chan_sip.c:8142 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True
[Nov 15 19:23:59] DEBUG[16656]: chan_sip.c:8143 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Nov 15 19:23:59] DEBUG[16656]: chan_sip.c:8296 add_sdp: -- Done with adding codecs to SDP
[Nov 15 19:23:59] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:23:59] DEBUG[16656]: chan_sip.c:8361 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Nov 15 19:23:59] DEBUG[16656]: chan_sip.c:2582 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 193.0.0.19:5060
[Nov 15 19:23:59] DEBUG[16630]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for SIP - 333222
[Nov 15 19:23:59] DEBUG[16630]: chan_sip.c:19464 sip_devicestate: Checking device state for peer 333222
[Nov 15 19:23:59] DEBUG[16630]: devicestate.c:441 do_state_change: Changing state for SIP/333222 - state 2 (In use)
[Nov 15 19:23:59] DEBUG[16642]: app_queue.c:763 handle_statechange: Device 'SIP/333222' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 15 19:23:59] DEBUG[16640]: chan_sip.c:6001 find_call: = Found Their Call ID: F7043F76-B27011DD-869FEFBE-C54E20A3@193.0.0.1 Their Tag E9E3ED64-4DC Our tag: as1171d0d3
[Nov 15 19:23:59] DEBUG[16640]: chan_sip.c:18333 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Nov 15 19:23:59] DEBUG[16640]: chan_sip.c:3059 __sip_ack: Stopping retransmission on 'F7043F76-B27011DD-869FEFBE-C54E20A3@193.0.0.1' of Response 101: Match Found
[Nov 15 19:24:00] DEBUG[16656]: channel.c:1720 __ast_answer: Didn't receive a voice frame from SIP/333222-0823fdb8 within 500 ms of answering. Continuing anyway
[Nov 15 19:24:00] DEBUG[16656]: pbx.c:3094 pbx_extension_helper: Launching 'BackGround'
    -- Executing [333222@maximash:3] BackGround("SIP/333222-0823fdb8", "intro") in new stack
[Nov 15 19:24:00] DEBUG[16656]: channel.c:3255 set_format: Set channel SIP/333222-0823fdb8 to write format gsm
[Nov 15 19:24:00] DEBUG[16656]: rtp.c:3169 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Nov 15 19:24:00] DEBUG[16656]: rtp.c:3185 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
    -- <SIP/333222-0823fdb8> Playing 'intro.gsm' (language 'en')
[Nov 15 19:24:02] DEBUG[16656]: sched.c:198 sched_settime: Request to schedule in the past?!?!
[Nov 15 19:24:04] DEBUG[16656]: channel.c:3255 set_format: Set channel SIP/333222-0823fdb8 to write format ulaw
[Nov 15 19:24:04] DEBUG[16656]: pbx.c:3094 pbx_extension_helper: Launching 'MusicOnHold'
    -- Executing [333222@maximash:4] MusicOnHold("SIP/333222-0823fdb8", "default,10") in new stack
    -- Started music on hold, class 'default', on SIP/333222-0823fdb8
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:3255 set_format: Set channel SIP/333222-0823fdb8 to write format slin
[Nov 15 19:24:04] DEBUG[16656]: res_musiconhold.c:285 ast_moh_files_next: SIP/333222-0823fdb8 Opened file 0 '/var/lib/asterisk/moh/fpm-world-mix'
[Nov 15 19:24:04] DEBUG[16656]: rtp.c:3020 ast_rtp_raw_write: Difference is 664, ms is 103
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:04] DEBUG[16656]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:24:08] DEBUG[16656]: rtp.c:1100 ast_rtcp_read: Got RTCP report of 132 bytes
[Nov 15 19:24:12] DEBUG[16656]: rtp.c:1100 ast_rtcp_read: Got RTCP report of 88 bytes
    -- Stopped music on hold on SIP/333222-0823fdb8
[Nov 15 19:24:14] DEBUG[16656]: channel.c:3255 set_format: Set channel SIP/333222-0823fdb8 to write format ulaw
[Nov 15 19:24:14] DEBUG[16656]: pbx.c:3094 pbx_extension_helper: Launching 'BackGround'
    -- Executing [333222@maximash:5] BackGround("SIP/333222-0823fdb8", "intro") in new stack
[Nov 15 19:24:14] DEBUG[16656]: channel.c:3255 set_format: Set channel SIP/333222-0823fdb8 to write format gsm
[Nov 15 19:24:14] DEBUG[16656]: rtp.c:3020 ast_rtp_raw_write: Difference is 77256, ms is 9677
    -- <SIP/333222-0823fdb8> Playing 'intro.gsm' (language 'en')
[Nov 15 19:24:17] DEBUG[16656]: rtp.c:1100 ast_rtcp_read: Got RTCP report of 132 bytes
[Nov 15 19:24:19] DEBUG[16656]: channel.c:3255 set_format: Set channel SIP/333222-0823fdb8 to write format ulaw
[Nov 15 19:24:19] DEBUG[16656]: pbx.c:3094 pbx_extension_helper: Launching 'Hangup'
    -- Executing [333222@maximash:6] Hangup("SIP/333222-0823fdb8", "") in new stack
[Nov 15 19:24:19] DEBUG[16656]: pbx.c:3724 __ast_pbx_run: Spawn extension (maximash,333222,6) exited non-zero on 'SIP/333222-0823fdb8'
  == Spawn extension (maximash, 333222, 6) exited non-zero on 'SIP/333222-0823fdb8'
[Nov 15 19:24:19] DEBUG[16656]: channel.c:1543 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/333222-0823fdb8'
[Nov 15 19:24:19] DEBUG[16656]: channel.c:1636 ast_hangup: Hanging up channel 'SIP/333222-0823fdb8'
[Nov 15 19:24:19] DEBUG[16656]: chan_sip.c:4794 sip_hangup: Hangup call SIP/333222-0823fdb8, SIP callid F7043F76-B27011DD-869FEFBE-C54E20A3@193.0.0.1
[Nov 15 19:24:19] DEBUG[16656]: chan_sip.c:2582 __sip_xmit: Trying to put 'BYE sip:44' onto UDP socket destined for 193.0.0.19:5060
[Nov 15 19:24:19] DEBUG[16656]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/333222
[Nov 15 19:24:19] DEBUG[16630]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for SIP - 333222
[Nov 15 19:24:19] DEBUG[16630]: chan_sip.c:19464 sip_devicestate: Checking device state for peer 333222
[Nov 15 19:24:19] DEBUG[16630]: devicestate.c:441 do_state_change: Changing state for SIP/333222 - state 1 (Not in use)
[Nov 15 19:24:19] DEBUG[16642]: app_queue.c:763 handle_statechange: Device 'SIP/333222' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 15 19:24:19] DEBUG[16640]: chan_sip.c:6001 find_call: = Found Their Call ID: F7043F76-B27011DD-869FEFBE-C54E20A3@193.0.0.1 Their Tag E9E3ED64-4DC Our tag: as1171d0d3
[Nov 15 19:24:19] DEBUG[16640]: chan_sip.c:3059 __sip_ack: Stopping retransmission on 'F7043F76-B27011DD-869FEFBE-C54E20A3@193.0.0.1' of Request 102: Match Found

simburelu · November 15, 2008, 5:59pm

exten => 333222,1,Wait(1)
exten => 333222,2,Answer
exten => 333222,n,Background(intro)
exten => 333222,n,Ringing
exten => 333222,n,Dial(OOH323/911,60,r)
exten => 333222,n,Hangup()

Not hearing ring back
…

[Nov 15 19:43:01] DEBUG[16726]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x827da48'
[Nov 15 19:43:01] DEBUG[16726]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x827da48'
[Nov 15 19:43:01] DEBUG[16726]: devicestate.c:441 do_state_change: Changing state for SIP/333222 - state 2 (In use)
[Nov 15 19:43:01] DEBUG[16738]: app_queue.c:763 handle_statechange: Device 'SIP/333222' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 15 19:43:02] DEBUG[16752]: pbx.c:3094 pbx_extension_helper: Launching 'Answer'
    -- Executing [333222@maximash:2] Answer("SIP/333222-082426d8", "") in new stack
[Nov 15 19:43:02] DEBUG[16752]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/333222
[Nov 15 19:43:02] DEBUG[16752]: chan_sip.c:4960 sip_answer: SIP answering channel: SIP/333222-082426d8
[Nov 15 19:43:02] DEBUG[16752]: chan_sip.c:8418 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 19:43:02] DEBUG[16752]: chan_sip.c:8142 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True
[Nov 15 19:43:02] DEBUG[16752]: chan_sip.c:8143 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Nov 15 19:43:02] DEBUG[16752]: chan_sip.c:8296 add_sdp: -- Done with adding codecs to SDP
[Nov 15 19:43:02] DEBUG[16752]: channel.c:2780 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Nov 15 19:43:02] DEBUG[16752]: chan_sip.c:8361 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Nov 15 19:43:02] DEBUG[16752]: chan_sip.c:2582 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 193.0.0.19:5060
[Nov 15 19:43:02] DEBUG[16726]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for SIP - 333222
[Nov 15 19:43:02] DEBUG[16726]: chan_sip.c:19464 sip_devicestate: Checking device state for peer 333222
[Nov 15 19:43:02] DEBUG[16726]: devicestate.c:441 do_state_change: Changing state for SIP/333222 - state 2 (In use)
[Nov 15 19:43:02] DEBUG[16738]: app_queue.c:763 handle_statechange: Device 'SIP/333222' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 15 19:43:02] DEBUG[16736]: chan_sip.c:6001 find_call: = Found Their Call ID: A0AC5B37-B27311DD-8750EFBE-C54E20A3@193.0.0.1 Their Tag E9F56080-220D Our tag: as459018b7
[Nov 15 19:43:02] DEBUG[16736]: chan_sip.c:18333 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Nov 15 19:43:02] DEBUG[16736]: chan_sip.c:3059 __sip_ack: Stopping retransmission on 'A0AC5B37-B27311DD-8750EFBE-C54E20A3@193.0.0.1' of Response 101: Match Found
[Nov 15 19:43:03] DEBUG[16752]: channel.c:1720 __ast_answer: Didn't receive a voice frame from SIP/333222-082426d8 within 500 ms of answering. Continuing anyway
[Nov 15 19:43:03] DEBUG[16752]: pbx.c:3094 pbx_extension_helper: Launching 'BackGround'
    -- Executing [333222@maximash:3] BackGround("SIP/333222-082426d8", "intro") in new stack
[Nov 15 19:43:03] DEBUG[16752]: channel.c:3255 set_format: Set channel SIP/333222-082426d8 to write format gsm
[Nov 15 19:43:03] DEBUG[16752]: rtp.c:3169 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Nov 15 19:43:03] DEBUG[16752]: rtp.c:3185 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
    -- <SIP/333222-082426d8> Playing 'intro.gsm' (language 'en')
[Nov 15 19:43:07] DEBUG[16752]: channel.c:3255 set_format: Set channel SIP/333222-082426d8 to write format ulaw
[Nov 15 19:43:07] DEBUG[16752]: pbx.c:3094 pbx_extension_helper: Launching 'Ringing'
    -- Executing [333222@maximash:4] Ringing("SIP/333222-082426d8", "") in new stack
[Nov 15 19:43:07] DEBUG[16752]: channel.c:2833 ast_indicate_data: Driver for channel 'SIP/333222-082426d8' does not support indication 3, emulating it
[Nov 15 19:43:07] DEBUG[16752]: channel.c:3255 set_format: Set channel SIP/333222-082426d8 to write format slin
[Nov 15 19:43:07] DEBUG[16752]: pbx.c:3094 pbx_extension_helper: Launching 'Dial'
    -- Executing [333222@maximash:5] Dial("SIP/333222-082426d8", "OOH323/911,60,r") in new stack
[Nov 15 19:43:07] DEBUG[16752]: channel.c:3764 ast_channel_inherit_variables: Not copying variable BACKGROUNDSTATUS.
[Nov 15 19:43:07] DEBUG[16752]: channel.c:3764 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Nov 15 19:43:07] DEBUG[16752]: channel.c:3764 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Nov 15 19:43:07] DEBUG[16752]: channel.c:3764 ast_channel_inherit_variables: Not copying variable SIPURI.
    -- Called 911
[Nov 15 19:43:07] DEBUG[16752]: channel.c:2833 ast_indicate_data: Driver for channel 'SIP/333222-082426d8' does not support indication 3, emulating it
[Nov 15 19:43:07] DEBUG[16752]: channel.c:3255 set_format: Set channel SIP/333222-082426d8 to write format ulaw
[Nov 15 19:43:07] DEBUG[16752]: channel.c:3255 set_format: Set channel SIP/333222-082426d8 to write format slin
[Nov 15 19:43:07] DEBUG[16732]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel OOH323/911
[Nov 15 19:43:07] DEBUG[16726]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for OOH323 - 911
[Nov 15 19:43:07] DEBUG[16726]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x826e530'
[Nov 15 19:43:07] DEBUG[16726]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x826e530'
[Nov 15 19:43:07] DEBUG[16726]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x826e530'
[Nov 15 19:43:07] DEBUG[16726]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x826e530'
[Nov 15 19:43:07] DEBUG[16726]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channe
...

simburelu · November 16, 2008, 6:10pm

top

david55 · November 17, 2008, 12:25pm


Lack of internal timing (global option and suitable time source, e.g. ztdummy) will often result in one way audio, especially if the phones do silence suppression.

Lack of internal timing (global option and suitable time source, e.g. ztdummy) will often result in one way audio, especially if the phones do silence suppression.

simburelu · November 17, 2008, 7:04pm

I can’t believe it!!! Setting ‘internal timing’ solved the problme!!! Thank you very much, David !!! Now I can hear the ringback tone!!!

How can i get rid of the “Avoiding initial deadlock for channel” ?

Asterisk Ready.
*CLI> [Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:6001 find_call: = No match Their Call ID: 2e0e4b2800dc919f724fdf5425359ba6@11.0.0.33 Their Tag 632a5da25d125eb133100e44333926c4.5ac6 Our tag: as64b4a853
[Nov 17 20:58:22] DEBUG[12317]: acl.c:490 ast_ouraddrfor: Found IP address for this socket
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:2681 ast_sip_ouraddrfor: Target address 193.0.0.19 is not local, substituting externip
  == Using SIP RTP CoS mark 5
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:3905 do_setnat: Setting NAT on RTP to Off
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:5935 sip_alloc: Allocating new SIP dialog for 9FE617B0-B41011DD-B7CDEFBE-C54E20A3@193.0.0.1 - INVITE (With RTP)
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:18333 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:3905 do_setnat: Setting NAT on RTP to On
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:7008 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:16841 handle_request_invite: Checking SIP call limits for device 333222
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:4485 update_call_counter: Updating call counter for incoming call
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:5357 sip_new: *** Our native formats are 0x4 (ulaw)
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:5358 sip_new: *** Joint capabilities are 0x4 (ulaw)
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:5359 sip_new: *** Our capabilities are 0x4 (ulaw)
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:5360 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:5388 sip_new: This channel will not be able to handle video.
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:10047 build_route: build_route: Record-Route hop: <sip:193.0.0.19;lr=on;ftag=F487EF84-212D>
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:17054 handle_request_invite: SIP/333222-0823df68: New call is still down.... Trying...
[Nov 17 20:58:22] DEBUG[12317]: chan_sip.c:2582 __sip_xmit: Trying to put 'SIP/2.0 10' onto UDP socket destined for 193.0.0.19:5060
[Nov 17 20:58:22] DEBUG[12317]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/333222
[Nov 17 20:58:22] DEBUG[12307]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for SIP - 333222
[Nov 17 20:58:22] DEBUG[12307]: chan_sip.c:19464 sip_devicestate: Checking device state for peer 333222
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12335]: pbx.c:3094 pbx_extension_helper: Launching 'Wait'
    -- Executing [333222@maximash:1] Wait("SIP/333222-0823df68", "1") in new stack
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x8203798'
[Nov 17 20:58:22] DEBUG[12307]: devicestate.c:441 do_state_change: Changing state for SIP/333222 - state 2 (In use)
[Nov 17 20:58:22] DEBUG[12319]: app_queue.c:763 handle_statechange: Device 'SIP/333222' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 17 20:58:23] DEBUG[12335]: pbx.c:3094 pbx_extension_helper: Launching 'Answer'
    -- Executing [333222@maximash:2] Answer("SIP/333222-0823df68", "") in new stack
[Nov 17 20:58:23] DEBUG[12335]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/333222
[Nov 17 20:58:23] DEBUG[12335]: chan_sip.c:4960 sip_answer: SIP answering channel: SIP/333222-0823df68
[Nov 17 20:58:23] DEBUG[12335]: chan_sip.c:8418 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 17 20:58:23] DEBUG[12335]: chan_sip.c:8142 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True
[Nov 17 20:58:23] DEBUG[12335]: chan_sip.c:8143 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Nov 17 20:58:23] DEBUG[12335]: chan_sip.c:8296 add_sdp: -- Done with adding codecs to SDP
[Nov 17 20:58:23] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:23] DEBUG[12335]: chan_sip.c:8361 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Nov 17 20:58:23] DEBUG[12335]: chan_sip.c:2582 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 193.0.0.19:5060
[Nov 17 20:58:23] DEBUG[12307]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for SIP - 333222
[Nov 17 20:58:23] DEBUG[12307]: chan_sip.c:19464 sip_devicestate: Checking device state for peer 333222
[Nov 17 20:58:23] DEBUG[12307]: devicestate.c:441 do_state_change: Changing state for SIP/333222 - state 2 (In use)
[Nov 17 20:58:23] DEBUG[12319]: app_queue.c:763 handle_statechange: Device 'SIP/333222' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 17 20:58:23] DEBUG[12317]: chan_sip.c:6001 find_call: = Found Their Call ID: 9FE617B0-B41011DD-B7CDEFBE-C54E20A3@193.0.0.1 Their Tag F487EF84-212D Our tag: as02e9e261
[Nov 17 20:58:23] DEBUG[12317]: chan_sip.c:18333 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Nov 17 20:58:23] DEBUG[12317]: chan_sip.c:3059 __sip_ack: Stopping retransmission on '9FE617B0-B41011DD-B7CDEFBE-C54E20A3@193.0.0.1' of Response 101: Match Found
[Nov 17 20:58:23] DEBUG[12335]: channel.c:1720 __ast_answer: Didn't receive a voice frame from SIP/333222-0823df68 within 500 ms of answering. Continuing anyway
[Nov 17 20:58:23] DEBUG[12335]: pbx.c:3094 pbx_extension_helper: Launching 'BackGround'
    -- Executing [333222@maximash:3] BackGround("SIP/333222-0823df68", "intro") in new stack
[Nov 17 20:58:23] DEBUG[12335]: channel.c:3255 set_format: Set channel SIP/333222-0823df68 to write format gsm
[Nov 17 20:58:23] DEBUG[12335]: rtp.c:3169 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Nov 17 20:58:23] DEBUG[12335]: rtp.c:3185 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Nov 17 20:58:23] DEBUG[12335]: channel.c:2215 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/333222-0823df68> Playing 'intro.gsm' (language 'en')
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2215 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2215 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 17 20:58:28] DEBUG[12335]: channel.c:3255 set_format: Set channel SIP/333222-0823df68 to write format ulaw
[Nov 17 20:58:28] DEBUG[12335]: pbx.c:3094 pbx_extension_helper: Launching 'Dial'
    -- Executing [333222@maximash:4] Dial("SIP/333222-0823df68", "OOH323/911,60") in new stack
[Nov 17 20:58:28] DEBUG[12335]: channel.c:3764 ast_channel_inherit_variables: Not copying variable BACKGROUNDSTATUS.
[Nov 17 20:58:28] DEBUG[12335]: channel.c:3764 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Nov 17 20:58:28] DEBUG[12335]: channel.c:3764 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Nov 17 20:58:28] DEBUG[12335]: channel.c:3764 ast_channel_inherit_variables: Not copying variable SIPURI.
    -- Called 911
[Nov 17 20:58:28] DEBUG[12313]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel OOH323/911
[Nov 17 20:58:28] DEBUG[12307]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for OOH323 - 911
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
[Nov 17 20:58:28] DEBUG[12307]: channel.c:1146 channel_find_locked: Avoiding initial deadlock for channel '0x82b18d8'
    -- OOH323/911-dc4c is ringing
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2833 ast_indicate_data: Driver for channel 'SIP/333222-0823df68' does not support indication 3, emulating it
[Nov 17 20:58:28] DEBUG[12335]: channel.c:3255 set_format: Set channel SIP/333222-0823df68 to write format slin
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2215 ast_settimeout: Scheduling timer at 160 sample intervals
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12307]: devicestate.c:441 do_state_change: Changing state for OOH323/911 - state 6 (Ringing)
[Nov 17 20:58:28] DEBUG[12319]: app_queue.c:763 handle_statechange: Device 'OOH323/911' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: rtp.c:3020 ast_rtp_raw_write: Difference is 1680, ms is 230
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:28] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:31] DEBUG[12317]: chan_sip.c:2956 __sip_autodestruct: Auto destroying SIP dialog '2e0e4b2800dc919f724fdf5425359ba6@11.0.0.33'
[Nov 17 20:58:31] DEBUG[12317]: chan_sip.c:4586 sip_destroy: Destroying SIP dialog 2e0e4b2800dc919f724fdf5425359ba6@11.0.0.33
[Nov 17 20:58:32] DEBUG[12335]: rtp.c:1100 ast_rtcp_read: Got RTCP report of 132 bytes
[Nov 17 20:58:38] DEBUG[12335]: rtp.c:1100 ast_rtcp_read: Got RTCP report of 112 bytes
[Nov 17 20:58:41] DEBUG[12335]: rtp.c:1100 ast_rtcp_read: Got RTCP report of 112 bytes
[Nov 17 20:58:42] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:42] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:42] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:42] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:42] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:42] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:42] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:42] DEBUG[12335]: channel.c:2780 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26)
[Nov 17 20:58:42] DEBUG[12317]: chan_sip.c:6001 find_call: = Found Their Call ID: 9FE617B0-B41011DD-B7CDEFBE-C54E20A3@193.0.0.1 Their Tag F487EF84-212D Our tag: as02e9e261
[Nov 17 20:58:42] DEBUG[12317]: chan_sip.c:18333 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Nov 17 20:58:42] DEBUG[12317]: chan_sip.c:2357 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 9FE617B0-B41011DD-B7CDEFBE-C54E20A3@193.0.0.1
[Nov 17 20:58:42] DEBUG[12317]: chan_sip.c:17857 handle_request_bye: Received bye, issuing owner hangup
[Nov 17 20:58:42] DEBUG[12317]: chan_sip.c:2582 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 193.0.0.19:5060
[Nov 17 20:58:42] DEBUG[12335]: channel.c:3255 set_format: Set channel SIP/333222-0823df68 to write format ulaw
[Nov 17 20:58:42] DEBUG[12335]: channel.c:2215 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 17 20:58:42] DEBUG[12335]: rtp.c:1832 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Nov 17 20:58:42] DEBUG[12335]: channel.c:1636 ast_hangup: Hanging up channel 'OOH323/911-dc4c'
[Nov 17 20:58:42] DEBUG[12335]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel OOH323/911
[Nov 17 20:58:42] DEBUG[12307]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for OOH323 - 911
[Nov 17 20:58:42] DEBUG[12307]: devicestate.c:441 do_state_change: Changing state for OOH323/911 - state 0 (Unknown)
[Nov 17 20:58:42] DEBUG[12319]: app_queue.c:763 handle_statechange: Device 'OOH323/911' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Nov 17 20:58:42] DEBUG[12335]: app_dial.c:1946 dial_exec_full: Exiting with DIALSTATUS=CANCEL.
[Nov 17 20:58:42] DEBUG[12335]: pbx.c:3724 __ast_pbx_run: Spawn extension (maximash,333222,4) exited non-zero on 'SIP/333222-0823df68'
  == Spawn extension (maximash, 333222, 4) exited non-zero on 'SIP/333222-0823df68'
[Nov 17 20:58:42] DEBUG[12335]: channel.c:1543 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/333222-0823df68'
[Nov 17 20:58:42] DEBUG[12335]: channel.c:1636 ast_hangup: Hanging up channel 'SIP/333222-0823df68'
[Nov 17 20:58:42] DEBUG[12335]: chan_sip.c:4794 sip_hangup: Hangup call SIP/333222-0823df68, SIP callid 9FE617B0-B41011DD-B7CDEFBE-C54E20A3@193.0.0.1
[Nov 17 20:58:42] DEBUG[12335]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/333222
[Nov 17 20:58:42] DEBUG[12307]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for SIP - 333222
[Nov 17 20:58:42] DEBUG[12307]: chan_sip.c:19464 sip_devicestate: Checking device state for peer 333222
[Nov 17 20:58:42] DEBUG[12307]: devicestate.c:441 do_state_change: Changing state for SIP/333222 - state 1 (Not in use)
[Nov 17 20:58:42] DEBUG[12319]: app_queue.c:763 handle_statechange: Device 'SIP/333222' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.

simburelu · November 18, 2008, 4:29pm

^top

simburelu · November 18, 2008, 8:49pm

^tom

simburelu · November 19, 2008, 12:51pm

^top

david55 · November 19, 2008, 12:55pm

You are supposed to wait 24 hours before bumping.

You should ignore debug messages unless there is a specific fault. However your trace does look close to reaching the maximum of 200 or so retries.

What is the specific fault?

What are you doing that might result in a channel being locked for a long time?

Topic		Replies	Views
Ring tone don't works correctly Asterisk Support	1	345	December 27, 2017
Stuck with interactive voice menu Asterisk Support	8	375	March 18, 2008
Call interface at same as play sound Asterisk Support	0	181	January 19, 2006
Suggestion wanted Asterisk Support	3	104	May 24, 2024
DIAL with m flag - heard music only after playback() Asterisk General	4	413	November 16, 2013

RingBack of Dial cmd after PlayBack cmd, 1.6

Related topics