answering calls weirdness
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@microcomaustralia.com.au SET [dialed_extension]=[2000] EXECUTE sofia/internal/1004@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@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@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@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@microcomaustralia.com.au set(ringback=) 2011-03-24 10:31:22.141503 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [ringback]=[UNDEF] EXECUTE sofia/internal/1004@microcomaustralia.com.au set(transfer_ringback=local_stream://moh) 2011-03-24 10:31:22.164352 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1004@microcomaustralia.com.au set(call_timeout=30) 2011-03-24 10:31:22.179416 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [call_timeout]=[30] EXECUTE sofia/internal/1004@microcomaustralia.com.au set(hangup_after_bridge=true) 2011-03-24 10:31:22.192366 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1004@microcomaustralia.com.au set(continue_on_fail=true) 2011-03-24 10:31:22.206368 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [continue_on_fail]=[true] EXECUTE sofia/internal/1004@microcomaustralia.com.au bridge([presence_id=1000@microcomaustralia.com.au]error/user_not_registered,FreeTDM/1/1,[presence_id=1001@microcomaustralia.com.au]error/user_not_registered,FreeTDM/2/1,[presence_id=1002@microcomaustralia.com.au]sofia/internal/sip:1002@192.168.2.13:5060,[presence_id=1003@microcomaustralia.com.au]sofia/internal/sip:1003@192.168.2.13:5061,[presence_id=1004@microcomaustralia.com.au]sofia/internal/sip:1004@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@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@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@microcomaustralia.com.au] 2011-03-24 10:31:24.697423 [NOTICE] switch_channel.c:779 New Channel sofia/internal/sip:1002@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@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@192.168.2.13:5060 [BREAK] 2011-03-24 10:31:24.752679 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1002@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@192.168.2.13:5060) State INIT 2011-03-24 10:31:24.758368 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1002@192.168.2.13:5060 SOFIA INIT 2011-03-24 10:31:24.777518 [DEBUG] mod_sofia.c:123 (sofia/internal/sip:1002@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@192.168.2.13:5060 [BREAK] 2011-03-24 10:31:24.777518 [DEBUG] sofia.c:4402 Channel sofia/internal/sip:1002@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@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@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@192.168.2.13:5060) Callstate Change DOWN -> RINGING 2011-03-24 10:31:24.799334 [INFO] sofia.c:709 sofia/internal/sip:1002@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@192.168.2.13:5060) State ROUTING 2011-03-24 10:31:24.808910 [DEBUG] sofia.c:4402 Channel sofia/internal/sip:1002@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@192.168.2.13:5060! 2011-03-24 10:31:24.815429 [DEBUG] mod_sofia.c:146 sofia/internal/sip:1002@192.168.2.13:5060 SOFIA ROUTING 2011-03-24 10:31:24.815429 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1002@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@192.168.2.13:5060 [BREAK] 2011-03-24 10:31:24.815429 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/sip:1002@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@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@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@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@microcomaustralia.com.au] 2011-03-24 10:31:24.819480 [NOTICE] switch_channel.c:779 New Channel sofia/internal/sip:1003@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@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@192.168.2.13:5061 [BREAK] 2011-03-24 10:31:24.865923 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1003@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@192.168.2.13:5061) State INIT 2011-03-24 10:31:24.872367 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1003@192.168.2.13:5061 SOFIA INIT 2011-03-24 10:31:24.897626 [DEBUG] mod_sofia.c:123 (sofia/internal/sip:1003@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@192.168.2.13:5061 [BREAK] 2011-03-24 10:31:24.898904 [DEBUG] sofia.c:4402 Channel sofia/internal/sip:1003@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@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@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@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@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@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@192.168.2.13:5061) State ROUTING 2011-03-24 10:31:24.947209 [DEBUG] mod_sofia.c:146 sofia/internal/sip:1003@192.168.2.13:5061 SOFIA ROUTING 2011-03-24 10:31:24.949210 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1003@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@192.168.2.13:5061 [BREAK] 2011-03-24 10:31:24.950890 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/sip:1003@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@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@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@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@microcomaustralia.com.au] 2011-03-24 10:31:24.960337 [NOTICE] switch_channel.c:779 New Channel sofia/internal/sip:1004@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@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@59.167.180.194) State NEW 2011-03-24 10:31:24.994428 [DEBUG] mod_sofia.c:3920 (sofia/internal/sip:1004@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@192.168.2.16 [BREAK] 2011-03-24 10:31:25.023275 [DEBUG] sofia.c:4402 Channel sofia/internal/1004@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@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@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@59.167.180.194 [BREAK] 2011-03-24 10:31:25.053356 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1004@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@59.167.180.194) State INIT 2011-03-24 10:31:25.055393 [DEBUG] mod_sofia.c:83 sofia/internal/1004@59.167.180.194 SOFIA INIT 2011-03-24 10:31:25.055393 [DEBUG] mod_sofia.c:123 (sofia/internal/1004@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@59.167.180.194 [BREAK] 2011-03-24 10:31:25.055393 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/1004@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@59.167.180.194) Running State Change CS_ROUTING 2011-03-24 10:31:25.055393 [DEBUG] switch_channel.c:1512 (sofia/internal/1004@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@59.167.180.194) State ROUTING 2011-03-24 10:31:25.055393 [DEBUG] mod_sofia.c:146 sofia/internal/1004@59.167.180.194 SOFIA ROUTING 2011-03-24 10:31:25.055393 [DEBUG] switch_core_state_machine.c:77 sofia/internal/1004@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@microcomaustralia.com.au>
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@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@microcomaustralia.com.au SET [dialed_extension]=[2000] EXECUTE sofia/internal/1004@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@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@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@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@microcomaustralia.com.au set(ringback=) 2011-03-24 10:31:22.141503 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [ringback]=[UNDEF] EXECUTE sofia/internal/1004@microcomaustralia.com.au set(transfer_ringback=local_stream://moh) 2011-03-24 10:31:22.164352 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1004@microcomaustralia.com.au set(call_timeout=30) 2011-03-24 10:31:22.179416 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [call_timeout]=[30] EXECUTE sofia/internal/1004@microcomaustralia.com.au set(hangup_after_bridge=true) 2011-03-24 10:31:22.192366 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1004@microcomaustralia.com.auset(continue_on_fail=true) 2011-03-24 10:31:22.206368 [DEBUG] mod_dptools.c:854 sofia/internal/1004@microcomaustralia.com.au SET [continue_on_fail]=[true] EXECUTE sofia/internal/1004@microcomaustralia.com.au bridge([presence_id=1000@microcomaustralia.com.au ]error/user_not_registered,FreeTDM/1/1,[presence_id= 1001@microcomaustralia.com.au ]error/user_not_registered,FreeTDM/2/1,[presence_id= 1002@microcomaustralia.com.au]sofia/internal/sip:1002@192.168.2.13:5060 ,[presence_id=1003@microcomaustralia.com.au]sofia/internal/ sip:1003@192.168.2.13:5061,[presence_id=1004@microcomaustralia.com.au ]sofia/internal/sip:1004@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@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@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@microcomaustralia.com.au] 2011-03-24 10:31:24.697423 [NOTICE] switch_channel.c:779 New Channel sofia/internal/sip:1002@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@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@192.168.2.13:5060 [BREAK] 2011-03-24 10:31:24.752679 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1002@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@192.168.2.13:5060) State INIT 2011-03-24 10:31:24.758368 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1002@192.168.2.13:5060 SOFIA INIT 2011-03-24 10:31:24.777518 [DEBUG] mod_sofia.c:123 (sofia/internal/sip:1002@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@192.168.2.13:5060 [BREAK] 2011-03-24 10:31:24.777518 [DEBUG] sofia.c:4402 Channel sofia/internal/sip:1002@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@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@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@192.168.2.13:5060) Callstate Change DOWN -> RINGING 2011-03-24 10:31:24.799334 [INFO] sofia.c:709 sofia/internal/sip:1002@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@192.168.2.13:5060) State ROUTING 2011-03-24 10:31:24.808910 [DEBUG] sofia.c:4402 Channel sofia/internal/sip:1002@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@192.168.2.13:5060! 2011-03-24 10:31:24.815429 [DEBUG] mod_sofia.c:146 sofia/internal/sip:1002@192.168.2.13:5060 SOFIA ROUTING 2011-03-24 10:31:24.815429 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1002@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@192.168.2.13:5060 [BREAK] 2011-03-24 10:31:24.815429 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/sip:1002@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@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@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@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@microcomaustralia.com.au] 2011-03-24 10:31:24.819480 [NOTICE] switch_channel.c:779 New Channel sofia/internal/sip:1003@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@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@192.168.2.13:5061 [BREAK] 2011-03-24 10:31:24.865923 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1003@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@192.168.2.13:5061) State INIT 2011-03-24 10:31:24.872367 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1003@192.168.2.13:5061 SOFIA INIT 2011-03-24 10:31:24.897626 [DEBUG] mod_sofia.c:123 (sofia/internal/sip:1003@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@192.168.2.13:5061 [BREAK] 2011-03-24 10:31:24.898904 [DEBUG] sofia.c:4402 Channel sofia/internal/sip:1003@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@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@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@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@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@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@192.168.2.13:5061) State ROUTING 2011-03-24 10:31:24.947209 [DEBUG] mod_sofia.c:146 sofia/internal/sip:1003@192.168.2.13:5061 SOFIA ROUTING 2011-03-24 10:31:24.949210 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1003@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@192.168.2.13:5061 [BREAK] 2011-03-24 10:31:24.950890 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/sip:1003@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@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@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@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@microcomaustralia.com.au] 2011-03-24 10:31:24.960337 [NOTICE] switch_channel.c:779 New Channel sofia/internal/sip:1004@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@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@59.167.180.194) State NEW 2011-03-24 10:31:24.994428 [DEBUG] mod_sofia.c:3920 (sofia/internal/sip:1004@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@192.168.2.16 [BREAK] 2011-03-24 10:31:25.023275 [DEBUG] sofia.c:4402 Channel sofia/internal/1004@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@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@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@59.167.180.194 [BREAK] 2011-03-24 10:31:25.053356 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1004@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@59.167.180.194) State INIT 2011-03-24 10:31:25.055393 [DEBUG] mod_sofia.c:83 sofia/internal/1004@59.167.180.194 SOFIA INIT 2011-03-24 10:31:25.055393 [DEBUG] mod_sofia.c:123 (sofia/internal/1004@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@59.167.180.194 [BREAK] 2011-03-24 10:31:25.055393 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/1004@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@59.167.180.194) Running State Change CS_ROUTING 2011-03-24 10:31:25.055393 [DEBUG] switch_channel.c:1512 (sofia/internal/1004@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@59.167.180.194) State ROUTING 2011-03-24 10:31:25.055393 [DEBUG] mod_sofia.c:146 sofia/internal/1004@59.167.180.194 SOFIA ROUTING 2011-03-24 10:31:25.055393 [DEBUG] switch_core_state_machine.c:77 sofia/internal/1004@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@microcomaustralia.com.au>
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
On 25 March 2011 06:44, Michael Collins <msc@freeswitch.org> wrote:
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.
That seems to require a username and password, without telling me how to register. How do I get a username and password? -- Brian May <brian@microcomaustralia.com.au>
On 25 March 2011 06:44, Michael Collins <msc@freeswitch.org> wrote:
Can you drop this into pastebin? pastebin.freeswitch.org. Also include the dialplan that is running all this.
freeswitch log: http://pastebin.freeswitch.org/15837 relevant part of the dialplan: http://pastebin.freeswitch.org/15838
Use the "freeswitch log" syntax highlighting because it makes it much easier to read. -MC
Not really sure about that. It seems to have put broken HTML or something before the first line??? "pan class="re0">" -- Brian May <brian@microcomaustralia.com.au>
I upgraded to the latest git version of freeswitch and reproduced the same issues. Latest log file now: http://pastebin.freeswitch.org/15860 Where does it get 6201 from? Surely freeswitch doesn't normally pull phone numbers out of thin air??? -- Brian May <brian@microcomaustralia.com.au>
On 26 March 2011 18:27, Brian May <brian@microcomaustralia.com.au> wrote:
I upgraded to the latest git version of freeswitch and reproduced the same issues.
Latest log file now:
http://pastebin.freeswitch.org/15860
Where does it get 6201 from? Surely freeswitch doesn't normally pull phone numbers out of thin air???
Also worth noting that this only occurs when dialing group numbers, calls to single destinations work fine. Also callerid seems to be broken, I suspect this broke when I updated to the latest freeswitch, I removed the patch to fix freetdm, is this still required? http://pastebin.freeswitch.org/15861 I would have hoped these changes had already been incorporated into the upstream repository by now... -- Brian May <brian@microcomaustralia.com.au>
On 26 March 2011 18:50, Brian May <brian@microcomaustralia.com.au> wrote:
On 26 March 2011 18:27, Brian May <brian@microcomaustralia.com.au> wrote:
I upgraded to the latest git version of freeswitch and reproduced the same issues.
Latest log file now:
http://pastebin.freeswitch.org/15860
Where does it get 6201 from? Surely freeswitch doesn't normally pull phone numbers out of thin air???
Also worth noting that this only occurs when dialing group numbers, calls to single destinations work fine.
Any ideas on how to debug this problem? It is kind of making freeswitch useless :-( -- Brian May <brian@microcomaustralia.com.au>
get a siptrace to go with the debug log you have - sofia global siptrace on -- View this message in context: http://freeswitch-users.2379917.n2.nabble.com/answering-calls-weirdness-tp62... Sent from the freeswitch-users mailing list archive at Nabble.com.
On 28 March 2011 15:07, Jeff Lenk <jeff@jefflenk.com> wrote:
get a siptrace to go with the debug log you have - sofia global siptrace on
Never mind, think I have resolved it. At the risk of looking very very silly, here goes: First I noticed the problem only occured when I included a certain phone (ATA box) in the group. I noticed that ATA box has call forwarding on busy setup, to phone number ... you guessed it ... 6201. So my guess is everything normally works fine, but just recently somebody left that phone off hook (will check when I get home), so all phone calls were getting redirected to ... 6201. In other words freeswitch was doing what is was suppose to do. Now just to fix callerid on the freetdm port since upgrading to the latest freeswitch. -- Brian May <brian@microcomaustralia.com.au>
On 28 March 2011 15:28, Brian May <brian@microcomaustralia.com.au> wrote:
So my guess is everything normally works fine, but just recently somebody left that phone off hook (will check when I get home), so all phone calls were getting redirected to ... 6201.
In other words freeswitch was doing what is was suppose to do.
Then again, after thinking about it, I don't consider this expected behaviour. If making a bridge to a group, and one of the phones in the group forwards the call to somewhere else, I would expect this should only affect the call to that phone, the other phones in the group should continue ringing. -- Brian May <brian@microcomaustralia.com.au>
participants (3)
-
Brian May
-
Jeff Lenk
-
Michael Collins