[Freeswitch-users] answering calls weirdness

Thu Mar 24 22:44:15 MSK 2011

Can you drop this into pastebin? pastebin.freeswitch.org. Also include the
dialplan that is running all this. Use the "freeswitch log" syntax
highlighting because it makes it much easier to read.

-MC

On Wed, Mar 23, 2011 at 4:49 PM, Brian May
<brian at microcomaustralia.com.au>wrote:

> When freeswitch answers the call, everything seems fine at first, but
> then it redirects the call to the magic number of 6201 which fails
> because I haven't defined this number anywhere. For an incoming SIP
> call the call is hang up after the first ring. For an incoming call
> from FreeDTM, callerid doesn't work, and the phone keeps ringing
> randomly until well after the caller has hang up. As it a result it is
> not possible to answer the incoming call.
>
> At first I thought maybe a problem with my analog telephone line, I
> think I have ruled this out now that I see similar logs for SIP calls.
>
> What is weird is that I haven't made any changes to the setup, and
> everything was working fine until yesterday.
>
> Here is an excerpt from my logs for an incoming SIP call. Where is
> this magic number of 6201 coming from? I did a grep of all my config
> files and came up with nothing.
>
> Last night I rebooted the box, it worked for one call, then failed for
> subsequent calls.
>
>
> Any ideas??
>
>
> Thanks
>
>
>
> 2011-03-24 10:31:22.061336 [DEBUG] mod_dptools.c:854
> sofia/internal/1004 at microcomaustralia.com.au SET
> [dialed_extension]=[2000]
> EXECUTE sofia/internal/1004 at microcomaustralia.com.au
> export(dialed_extension=2000)
> 2011-03-24 10:31:22.080434 [DEBUG] mod_dptools.c:938 EXPORT
> [dialed_extension]=[2000]
> EXECUTE sofia/internal/1004 at microcomaustralia.com.au bind_meta_app(1 b
> s execute_extension::dx XML features)
> 2011-03-24 10:31:22.095423 [INFO] switch_ivr_async.c:2464 Bound B-Leg:
> *1 execute_extension::dx XML features
> EXECUTE sofia/internal/1004 at microcomaustralia.com.au bind_meta_app(2 b
> s record_session::/opt/freeswitch/recordings/1004.2011-03-24-10-31-22.wav)
> 2011-03-24 10:31:22.116351 [INFO] switch_ivr_async.c:2464 Bound B-Leg:
> *2 record_session::/opt/freeswitch/recordings/1004.2011-03-24-10-31-22.wav
> EXECUTE sofia/internal/1004 at microcomaustralia.com.au bind_meta_app(3 b
> s execute_extension::cf XML features)
> 2011-03-24 10:31:22.130335 [INFO] switch_ivr_async.c:2464 Bound B-Leg:
> *3 execute_extension::cf XML features
> EXECUTE sofia/internal/1004 at microcomaustralia.com.au set(ringback=)
> 2011-03-24 10:31:22.141503 [DEBUG] mod_dptools.c:854
> sofia/internal/1004 at microcomaustralia.com.au SET [ringback]=[UNDEF]
> EXECUTE sofia/internal/1004 at microcomaustralia.com.au
> set(transfer_ringback=local_stream://moh)
> 2011-03-24 10:31:22.164352 [DEBUG] mod_dptools.c:854
> sofia/internal/1004 at microcomaustralia.com.au SET
> [transfer_ringback]=[local_stream://moh]
> EXECUTE sofia/internal/1004 at microcomaustralia.com.au set(call_timeout=30)
> 2011-03-24 10:31:22.179416 [DEBUG] mod_dptools.c:854
> sofia/internal/1004 at microcomaustralia.com.au SET [call_timeout]=[30]
> EXECUTE sofia/internal/1004 at microcomaustralia.com.au
> set(hangup_after_bridge=true)
> 2011-03-24 10:31:22.192366 [DEBUG] mod_dptools.c:854
> sofia/internal/1004 at microcomaustralia.com.au SET
> [hangup_after_bridge]=[true]
> EXECUTE sofia/internal/1004 at microcomaustralia.com.auset(continue_on_fail=true)
> 2011-03-24 10:31:22.206368 [DEBUG] mod_dptools.c:854
> sofia/internal/1004 at microcomaustralia.com.au SET
> [continue_on_fail]=[true]
> EXECUTE sofia/internal/1004 at microcomaustralia.com.au
> bridge([presence_id=1000 at microcomaustralia.com.au
> ]error/user_not_registered,FreeTDM/1/1,[presence_id=
> 1001 at microcomaustralia.com.au
> ]error/user_not_registered,FreeTDM/2/1,[presence_id=
> 1002 at microcomaustralia.com.au]sofia/internal/sip:1002 at 192.168.2.13:5060
> ,[presence_id=1003 at microcomaustralia.com.au]sofia/internal/
> sip:1003 at 192.168.2.13:5061,[presence_id=1004 at microcomaustralia.com.au
> ]sofia/internal/sip:1004 at 192.168.2.16)
>
> Everything fine up to (and beyond) this point.
>
>
> 2011-03-24 10:31:22.374349 [DEBUG] switch_ivr_originate.c:2599 local
> variable string 0 = [presence_id=1000 at microcomaustralia.com.au]
> 2011-03-24 10:31:22.374349 [ERR] switch_ivr_originate.c:2632 Cannot
> create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
> 2011-03-24 10:31:22.380323 [INFO] ftmod_zt.c:636 Setting echo cancel
> to 64 taps for 1:1
> 2011-03-24 10:31:22.381586 [DEBUG] mod_freetdm.c:377 Set codec PCMU 20ms
> 2011-03-24 10:31:22.393312 [DEBUG] mod_freetdm.c:1334 Connect outbound
> channel FreeTDM/1:1/
> 2011-03-24 10:31:22.393312 [NOTICE] switch_channel.c:779 New Channel
> FreeTDM/1:1/ [d1b1124a-e8cf-485a-8c1e-dafbcaf0d09b]
> 2011-03-24 10:31:22.399504 [DEBUG] mod_freetdm.c:1348 (FreeTDM/1:1/)
> State Change CS_NEW -> CS_INIT
> 2011-03-24 10:31:22.399504 [DEBUG] switch_core_session.c:1047 Send
> signal FreeTDM/1:1/ [BREAK]
> 2011-03-24 10:31:22.399504 [DEBUG] ftmod_analog.c:361 [s1c1][1:1]
> ANALOG CHANNEL thread starting.
> 2011-03-24 10:31:22.404683 [DEBUG] ftmod_analog.c:88 [s1c1][1:1]
> Changed state from DOWN to GENRING
> 2011-03-24 10:31:23.514411 [INFO] ftmod_zt.c:636 Setting echo cancel
> to 64 taps for 1:1
> 2011-03-24 10:31:23.514411 [DEBUG] ftdm_io.c:2539 [s1c1][1:1] Enabled
> software DTMF detector
> 2011-03-24 10:31:23.514411 [DEBUG] ftmod_analog.c:381 [s1c1][1:1]
> Initialized DTMF detection
> 2011-03-24 10:31:23.514411 [DEBUG] ftmod_analog.c:534 [s1c1][1:1]
> Executing state handler on 1:1 for GENRING
> 2011-03-24 10:31:23.514411 [DEBUG] mod_freetdm.c:1715 got FXS sig
> [PROGRESS]
> 2011-03-24 10:31:23.514411 [NOTICE] mod_freetdm.c:1732 Ring-Ready
> FreeTDM/1:1/!
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_state_machine.c:314
> (FreeTDM/1:1/) Running State Change CS_INIT
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_state_machine.c:338
> (FreeTDM/1:1/) State INIT
> 2011-03-24 10:31:23.525898 [DEBUG] mod_freetdm.c:405 (FreeTDM/1:1/)
> State Change CS_INIT -> CS_ROUTING
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_session.c:1047 Send
> signal FreeTDM/1:1/ [BREAK]
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_state_machine.c:338
> (FreeTDM/1:1/) State INIT going to sleep
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_state_machine.c:314
> (FreeTDM/1:1/) Running State Change CS_ROUTING
> 2011-03-24 10:31:23.525898 [DEBUG] switch_channel.c:1512
> (FreeTDM/1:1/) Callstate Change DOWN -> RINGING
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_state_machine.c:341
> (FreeTDM/1:1/) State ROUTING
> 2011-03-24 10:31:23.525898 [DEBUG] mod_freetdm.c:428 FreeTDM/1:1/
> CHANNEL ROUTING
> 2011-03-24 10:31:23.525898 [DEBUG] switch_ivr_originate.c:66
> (FreeTDM/1:1/) State Change CS_ROUTING -> CS_CONSUME_MEDIA
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_session.c:1047 Send
> signal FreeTDM/1:1/ [BREAK]
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_state_machine.c:341
> (FreeTDM/1:1/) State ROUTING going to sleep
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_state_machine.c:314
> (FreeTDM/1:1/) Running State Change CS_CONSUME_MEDIA
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_state_machine.c:360
> (FreeTDM/1:1/) State CONSUME_MEDIA
> 2011-03-24 10:31:23.525898 [DEBUG] switch_core_state_machine.c:360
> (FreeTDM/1:1/) State CONSUME_MEDIA going to sleep
> 2011-03-24 10:31:23.536490 [DEBUG] switch_ivr_originate.c:2599 local
> variable string 0 = [presence_id=1001 at microcomaustralia.com.au]
> 2011-03-24 10:31:23.538398 [ERR] switch_ivr_originate.c:2632 Cannot
> create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
> 2011-03-24 10:31:23.538398 [INFO] ftmod_zt.c:636 Setting echo cancel
> to 64 taps for 2:1
> 2011-03-24 10:31:23.544342 [DEBUG] mod_freetdm.c:377 Set codec PCMU 20ms
> 2011-03-24 10:31:23.551431 [DEBUG] mod_freetdm.c:1334 Connect outbound
> channel FreeTDM/2:1/
> 2011-03-24 10:31:23.555384 [NOTICE] switch_channel.c:779 New Channel
> FreeTDM/2:1/ [86275359-c4be-4663-9561-c5973344c1a7]
> 2011-03-24 10:31:23.559646 [DEBUG] mod_freetdm.c:1348 (FreeTDM/2:1/)
> State Change CS_NEW -> CS_INIT
> 2011-03-24 10:31:23.561459 [DEBUG] switch_core_session.c:1047 Send
> signal FreeTDM/2:1/ [BREAK]
> 2011-03-24 10:31:23.561459 [DEBUG] ftmod_analog.c:361 [s2c1][1:2]
> ANALOG CHANNEL thread starting.
> 2011-03-24 10:31:23.565467 [DEBUG] ftmod_analog.c:88 [s2c1][1:2]
> Changed state from DOWN to GENRING
> 2011-03-24 10:31:24.665349 [INFO] ftmod_zt.c:636 Setting echo cancel
> to 64 taps for 2:1
> 2011-03-24 10:31:24.665349 [DEBUG] ftdm_io.c:2539 [s2c1][1:2] Enabled
> software DTMF detector
> 2011-03-24 10:31:24.665349 [DEBUG] ftmod_analog.c:381 [s2c1][1:2]
> Initialized DTMF detection
> 2011-03-24 10:31:24.665349 [DEBUG] ftmod_analog.c:534 [s2c1][1:2]
> Executing state handler on 2:1 for GENRING
> 2011-03-24 10:31:24.665349 [DEBUG] mod_freetdm.c:1715 got FXS sig
> [PROGRESS]
> 2011-03-24 10:31:24.665349 [NOTICE] mod_freetdm.c:1732 Ring-Ready
> FreeTDM/2:1/!
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_state_machine.c:314
> (FreeTDM/2:1/) Running State Change CS_INIT
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_state_machine.c:338
> (FreeTDM/2:1/) State INIT
> 2011-03-24 10:31:24.677691 [DEBUG] mod_freetdm.c:405 (FreeTDM/2:1/)
> State Change CS_INIT -> CS_ROUTING
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_session.c:1047 Send
> signal FreeTDM/2:1/ [BREAK]
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_state_machine.c:338
> (FreeTDM/2:1/) State INIT going to sleep
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_state_machine.c:314
> (FreeTDM/2:1/) Running State Change CS_ROUTING
> 2011-03-24 10:31:24.677691 [DEBUG] switch_channel.c:1512
> (FreeTDM/2:1/) Callstate Change DOWN -> RINGING
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_state_machine.c:341
> (FreeTDM/2:1/) State ROUTING
> 2011-03-24 10:31:24.677691 [DEBUG] mod_freetdm.c:428 FreeTDM/2:1/
> CHANNEL ROUTING
> 2011-03-24 10:31:24.677691 [DEBUG] switch_ivr_originate.c:66
> (FreeTDM/2:1/) State Change CS_ROUTING -> CS_CONSUME_MEDIA
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_session.c:1047 Send
> signal FreeTDM/2:1/ [BREAK]
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_state_machine.c:341
> (FreeTDM/2:1/) State ROUTING going to sleep
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_state_machine.c:314
> (FreeTDM/2:1/) Running State Change CS_CONSUME_MEDIA
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_state_machine.c:360
> (FreeTDM/2:1/) State CONSUME_MEDIA
> 2011-03-24 10:31:24.677691 [DEBUG] switch_core_state_machine.c:360
> (FreeTDM/2:1/) State CONSUME_MEDIA going to sleep
> 2011-03-24 10:31:24.692818 [DEBUG] switch_ivr_originate.c:2599 local
> variable string 0 = [presence_id=1002 at microcomaustralia.com.au]
> 2011-03-24 10:31:24.697423 [NOTICE] switch_channel.c:779 New Channel
> sofia/internal/sip:1002 at 192.168.2.13:5060
> [0da6383c-4633-4a03-99ed-839918a74161]
> 2011-03-24 10:31:24.737484 [DEBUG] mod_sofia.c:3920
> (sofia/internal/sip:1002 at 192.168.2.13:5060) State Change CS_NEW ->
> CS_INIT
> 2011-03-24 10:31:24.737484 [DEBUG] switch_core_session.c:1047 Send
> signal sofia/internal/sip:1002 at 192.168.2.13:5060 [BREAK]
> 2011-03-24 10:31:24.752679 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1002 at 192.168.2.13:5060) Running State Change
> CS_INIT
> 2011-03-24 10:31:24.756503 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/sip:1002 at 192.168.2.13:5060) State INIT
> 2011-03-24 10:31:24.758368 [DEBUG] mod_sofia.c:83
> sofia/internal/sip:1002 at 192.168.2.13:5060 SOFIA INIT
> 2011-03-24 10:31:24.777518 [DEBUG] mod_sofia.c:123
> (sofia/internal/sip:1002 at 192.168.2.13:5060) State Change CS_INIT ->
> CS_ROUTING
> 2011-03-24 10:31:24.777518 [DEBUG] switch_core_session.c:1047 Send
> signal sofia/internal/sip:1002 at 192.168.2.13:5060 [BREAK]
> 2011-03-24 10:31:24.777518 [DEBUG] sofia.c:4402 Channel
> sofia/internal/sip:1002 at 192.168.2.13:5060 entering state [calling][0]
> 2011-03-24 10:31:24.781657 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/sip:1002 at 192.168.2.13:5060) State INIT going to sleep
> 2011-03-24 10:31:24.781657 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1002 at 192.168.2.13:5060) Running State Change
> CS_ROUTING
> 2011-03-24 10:31:24.785366 [DEBUG] switch_channel.c:1512
> (sofia/internal/sip:1002 at 192.168.2.13:5060) Callstate Change DOWN ->
> RINGING
> 2011-03-24 10:31:24.799334 [INFO] sofia.c:709
> sofia/internal/sip:1002 at 192.168.2.13:5060 Update Callee ID to "1002"
> <1002>
> 2011-03-24 10:31:24.808910 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/sip:1002 at 192.168.2.13:5060) State ROUTING
> 2011-03-24 10:31:24.808910 [DEBUG] sofia.c:4402 Channel
> sofia/internal/sip:1002 at 192.168.2.13:5060 entering state
> [proceeding][180]
> 2011-03-24 10:31:24.812354 [NOTICE] sofia.c:4474 Ring-Ready
> sofia/internal/sip:1002 at 192.168.2.13:5060!
> 2011-03-24 10:31:24.815429 [DEBUG] mod_sofia.c:146
> sofia/internal/sip:1002 at 192.168.2.13:5060 SOFIA ROUTING
> 2011-03-24 10:31:24.815429 [DEBUG] switch_ivr_originate.c:66
> (sofia/internal/sip:1002 at 192.168.2.13:5060) State Change CS_ROUTING ->
> CS_CONSUME_MEDIA
> 2011-03-24 10:31:24.815429 [DEBUG] switch_core_session.c:1047 Send
> signal sofia/internal/sip:1002 at 192.168.2.13:5060 [BREAK]
> 2011-03-24 10:31:24.815429 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/sip:1002 at 192.168.2.13:5060) State ROUTING going to
> sleep
> 2011-03-24 10:31:24.815429 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1002 at 192.168.2.13:5060) Running State Change
> CS_CONSUME_MEDIA
> 2011-03-24 10:31:24.817284 [DEBUG] switch_core_state_machine.c:360
> (sofia/internal/sip:1002 at 192.168.2.13:5060) State CONSUME_MEDIA
> 2011-03-24 10:31:24.817284 [DEBUG] switch_core_state_machine.c:360
> (sofia/internal/sip:1002 at 192.168.2.13:5060) State CONSUME_MEDIA going
> to sleep
> 2011-03-24 10:31:24.819480 [DEBUG] switch_ivr_originate.c:2599 local
> variable string 0 = [presence_id=1003 at microcomaustralia.com.au]
> 2011-03-24 10:31:24.819480 [NOTICE] switch_channel.c:779 New Channel
> sofia/internal/sip:1003 at 192.168.2.13:5061
> [644a2402-7658-4831-8599-2439dc82e1f2]
> 2011-03-24 10:31:24.850900 [DEBUG] mod_sofia.c:3920
> (sofia/internal/sip:1003 at 192.168.2.13:5061) State Change CS_NEW ->
> CS_INIT
> 2011-03-24 10:31:24.851903 [DEBUG] switch_core_session.c:1047 Send
> signal sofia/internal/sip:1003 at 192.168.2.13:5061 [BREAK]
> 2011-03-24 10:31:24.865923 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1003 at 192.168.2.13:5061) Running State Change
> CS_INIT
> 2011-03-24 10:31:24.865923 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/sip:1003 at 192.168.2.13:5061) State INIT
> 2011-03-24 10:31:24.872367 [DEBUG] mod_sofia.c:83
> sofia/internal/sip:1003 at 192.168.2.13:5061 SOFIA INIT
> 2011-03-24 10:31:24.897626 [DEBUG] mod_sofia.c:123
> (sofia/internal/sip:1003 at 192.168.2.13:5061) State Change CS_INIT ->
> CS_ROUTING
> 2011-03-24 10:31:24.898904 [DEBUG] switch_core_session.c:1047 Send
> signal sofia/internal/sip:1003 at 192.168.2.13:5061 [BREAK]
> 2011-03-24 10:31:24.898904 [DEBUG] sofia.c:4402 Channel
> sofia/internal/sip:1003 at 192.168.2.13:5061 entering state [calling][0]
> 2011-03-24 10:31:24.899882 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/sip:1003 at 192.168.2.13:5061) State INIT going to sleep
> 2011-03-24 10:31:24.899882 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1003 at 192.168.2.13:5061) Running State Change
> CS_ROUTING
> 2011-03-24 10:31:24.920400 [DEBUG] sofia.c:4402 Channel
> sofia/internal/sip:1003 at 192.168.2.13:5061 entering state [calling][0]
> 2011-03-24 10:31:24.930315 [DEBUG] sofia.c:6117 IP 59.167.180.194
> Rejected by acl "domains". Falling back to Digest auth.
> 2011-03-24 10:31:24.930315 [NOTICE] switch_channel.c:779 New Channel
> sofia/internal/1004 at 59.167.180.194
> [294c0493-b397-481a-ac78-09fa727d79b9]
> 2011-03-24 10:31:24.939488 [DEBUG] switch_channel.c:1512
> (sofia/internal/sip:1003 at 192.168.2.13:5061) Callstate Change DOWN ->
> RINGING
> 2011-03-24 10:31:24.947209 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/sip:1003 at 192.168.2.13:5061) State ROUTING
> 2011-03-24 10:31:24.947209 [DEBUG] mod_sofia.c:146
> sofia/internal/sip:1003 at 192.168.2.13:5061 SOFIA ROUTING
> 2011-03-24 10:31:24.949210 [DEBUG] switch_ivr_originate.c:66
> (sofia/internal/sip:1003 at 192.168.2.13:5061) State Change CS_ROUTING ->
> CS_CONSUME_MEDIA
> 2011-03-24 10:31:24.950890 [DEBUG] switch_core_session.c:1047 Send
> signal sofia/internal/sip:1003 at 192.168.2.13:5061 [BREAK]
> 2011-03-24 10:31:24.950890 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/sip:1003 at 192.168.2.13:5061) State ROUTING going to
> sleep
> 2011-03-24 10:31:24.950890 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1003 at 192.168.2.13:5061) Running State Change
> CS_CONSUME_MEDIA
> 2011-03-24 10:31:24.954269 [DEBUG] switch_core_state_machine.c:360
> (sofia/internal/sip:1003 at 192.168.2.13:5061) State CONSUME_MEDIA
> 2011-03-24 10:31:24.954269 [DEBUG] switch_core_state_machine.c:360
> (sofia/internal/sip:1003 at 192.168.2.13:5061) State CONSUME_MEDIA going
> to sleep
> 2011-03-24 10:31:24.954269 [DEBUG] switch_ivr_originate.c:2599 local
> variable string 0 = [presence_id=1004 at microcomaustralia.com.au]
> 2011-03-24 10:31:24.960337 [NOTICE] switch_channel.c:779 New Channel
> sofia/internal/sip:1004 at 192.168.2.16
> [55c3e984-ddf8-45db-a157-65c50e18c8d0]
> 2011-03-24 10:31:24.970358 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/1004 at 59.167.180.194) Running State Change CS_NEW
> 2011-03-24 10:31:24.970358 [DEBUG] switch_core_state_machine.c:320
> (sofia/internal/1004 at 59.167.180.194) State NEW
> 2011-03-24 10:31:24.994428 [DEBUG] mod_sofia.c:3920
> (sofia/internal/sip:1004 at 192.168.2.16) State Change CS_NEW -> CS_INIT
> 2011-03-24 10:31:24.996392 [DEBUG] switch_core_session.c:1047 Send
> signal sofia/internal/sip:1004 at 192.168.2.16 [BREAK]
> 2011-03-24 10:31:25.023275 [DEBUG] sofia.c:4402 Channel
> sofia/internal/1004 at 59.167.180.194 entering state [received][100]
> 2011-03-24 10:31:25.029365 [DEBUG] sofia.c:4413 Remote SDP:
> v=0
> o=FreeSWITCH 1300899030 1300899032 IN IP4 59.167.180.194
> s=FreeSWITCH
> c=IN IP4 59.167.180.194
> t=0 0
> m=audio 24054 RTP/AVP 8 115 107 0 101
> a=rtpmap:8 PCMA/8000
> a=rtpmap:115 G7221/32000
> a=fmtp:115 bitrate=48000
> a=rtpmap:107 G7221/16000
> a=fmtp:107 bitrate=32000
> a=rtpmap:0 PCMU/8000
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=silenceSupp:off - - - -
> a=ptime:20
>
> 2011-03-24 10:31:25.035447 [DEBUG] sofia_glue.c:3859 Audio Codec
> Compare [PCMA:8:8000:20]/[G7221:115:32000:20]
> 2011-03-24 10:31:25.035447 [DEBUG] sofia_glue.c:3859 Audio Codec
> Compare [PCMA:8:8000:20]/[G7221:107:16000:20]
> 2011-03-24 10:31:25.035447 [DEBUG] sofia_glue.c:3859 Audio Codec
> Compare [PCMA:8:8000:20]/[PCMU:0:8000:20]
> 2011-03-24 10:31:25.035447 [DEBUG] sofia_glue.c:3859 Audio Codec
> Compare [PCMA:8:8000:20]/[PCMA:8:8000:20]
> 2011-03-24 10:31:25.037256 [DEBUG] sofia_glue.c:2454 Set Codec
> sofia/internal/1004 at 59.167.180.194 PCMA/8000 20 ms 160 samples
> 2011-03-24 10:31:25.049229 [DEBUG] sofia_glue.c:3955 Set 2833 dtmf
> send/recv payload to 101
> 2011-03-24 10:31:25.049229 [DEBUG] sofia.c:4573
> (sofia/internal/1004 at 59.167.180.194) State Change CS_NEW -> CS_INIT
> 2011-03-24 10:31:25.049229 [DEBUG] switch_core_session.c:1047 Send
> signal sofia/internal/1004 at 59.167.180.194 [BREAK]
> 2011-03-24 10:31:25.053356 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/1004 at 59.167.180.194) Running State Change CS_INIT
> 2011-03-24 10:31:25.053356 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/1004 at 59.167.180.194) State INIT
> 2011-03-24 10:31:25.055393 [DEBUG] mod_sofia.c:83
> sofia/internal/1004 at 59.167.180.194 SOFIA INIT
> 2011-03-24 10:31:25.055393 [DEBUG] mod_sofia.c:123
> (sofia/internal/1004 at 59.167.180.194) State Change CS_INIT ->
> CS_ROUTING
> 2011-03-24 10:31:25.055393 [DEBUG] switch_core_session.c:1047 Send
> signal sofia/internal/1004 at 59.167.180.194 [BREAK]
> 2011-03-24 10:31:25.055393 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/1004 at 59.167.180.194) State INIT going to sleep
> 2011-03-24 10:31:25.055393 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/1004 at 59.167.180.194) Running State Change CS_ROUTING
> 2011-03-24 10:31:25.055393 [DEBUG] switch_channel.c:1512
> (sofia/internal/1004 at 59.167.180.194) Callstate Change DOWN -> RINGING
> 2011-03-24 10:31:25.055393 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/1004 at 59.167.180.194) State ROUTING
> 2011-03-24 10:31:25.055393 [DEBUG] mod_sofia.c:146
> sofia/internal/1004 at 59.167.180.194 SOFIA ROUTING
> 2011-03-24 10:31:25.055393 [DEBUG] switch_core_state_machine.c:77
> sofia/internal/1004 at 59.167.180.194 Standard ROUTING
> 2011-03-24 10:31:25.055393 [INFO] mod_dialplan_xml.c:331 Processing
> Brian May <1004>->6201 in context public
>
>
> Something went wrong here. It starts processing 6201 as per normal.
> --
> Brian May <brian at microcomaustralia.com.au>
>
> _______________________________________________
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20110324/b5bb69b6/attachment-0001.html 