[Freeswitch-users] answering calls weirdness

Thu Mar 24 02:49:52 MSK 2011

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.au set(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>