2009-11-03 15:39:50.762957 [DEBUG] sofia.c:5067 0 acls to check for proxy 2009-11-03 15:39:50.762957 [DEBUG] sofia.c:5085 network ip is a proxy [0] 2009-11-03 15:39:50.762957 [DEBUG] sofia.c:5113 IP 10.86.10.58 Rejected by acl "domains". Falling back to Digest auth. 2009-11-03 15:39:50.780028 [DEBUG] sofia.c:5067 0 acls to check for proxy 2009-11-03 15:39:50.780028 [DEBUG] sofia.c:5085 network ip is a proxy [0] 2009-11-03 15:39:50.780028 [DEBUG] sofia.c:5113 IP 10.86.10.58 Rejected by acl "domains". Falling back to Digest auth. 2009-11-03 15:39:50.797901 [NOTICE] switch_channel.c:613 New Channel sofia/internal/1000@nshplpbx1.unix [8c133ad4-67cf-4ffa-8655-56ffa0e3933d] 2009-11-03 15:39:50.799061 [DEBUG] sofia.c:5812 Setting NAT mode based on nat.auto 2009-11-03 15:39:50.799061 [DEBUG] sofia.c:3588 Channel sofia/internal/1000@nshplpbx1.unix entering state [received][100] 2009-11-03 15:39:50.799061 [DEBUG] sofia.c:3599 Remote SDP: v=0 o=- 8 2 IN IP4 10.86.10.58 s=CounterPath X-Lite 3.0 c=IN IP4 10.86.10.58 t=0 0 m=audio 37250 RTP/AVP 107 0 8 101 a=rtpmap:107 BV32/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=alt:1 1 : cwKnUvoi NsQWtT4P 10.86.10.58 37250 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [BV32:107:16000:0]/[G7221:115:32000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [BV32:107:16000:0]/[G7221:107:16000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [BV32:107:16000:0]/[G722:9:8000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [BV32:107:16000:0]/[PCMU:0:8000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [BV32:107:16000:0]/[PCMA:8:8000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [BV32:107:16000:0]/[GSM:3:8000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [PCMU:0:8000:0]/[G7221:115:32000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [PCMU:0:8000:0]/[G7221:107:16000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [PCMU:0:8000:0]/[G722:9:8000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3160 Audio Codec Compare [PCMU:0:8000:0]/[PCMU:0:8000:20] 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:2102 Set Codec sofia/internal/1000@nshplpbx1.unix PCMU/8000 20 ms 160 samples 2009-11-03 15:39:50.799061 [DEBUG] sofia_glue.c:3120 Set 2833 dtmf payload to 101 2009-11-03 15:39:50.799061 [DEBUG] sofia.c:3744 (sofia/internal/1000@nshplpbx1.unix) State Change CS_NEW -> CS_INIT 2009-11-03 15:39:50.799061 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:50.799061 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_INIT 2009-11-03 15:39:50.799061 [DEBUG] switch_core_state_machine.c:330 (sofia/internal/1000@nshplpbx1.unix) State INIT 2009-11-03 15:39:50.799061 [DEBUG] mod_sofia.c:83 sofia/internal/1000@nshplpbx1.unix SOFIA INIT 2009-11-03 15:39:50.799061 [DEBUG] mod_sofia.c:111 (sofia/internal/1000@nshplpbx1.unix) State Change CS_INIT -> CS_ROUTING 2009-11-03 15:39:50.799061 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:330 (sofia/internal/1000@nshplpbx1.unix) State INIT going to sleep 2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_ROUTING 2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1000@nshplpbx1.unix) State ROUTING 2009-11-03 15:39:50.800189 [DEBUG] mod_sofia.c:130 sofia/internal/1000@nshplpbx1.unix SOFIA ROUTING 2009-11-03 15:39:50.800189 [DEBUG] switch_core_state_machine.c:78 sofia/internal/1000@nshplpbx1.unix Standard ROUTING 2009-11-03 15:39:50.800189 [INFO] mod_dialplan_xml.c:397 Processing 1000->1008 in context default Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->unloop] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->tod_example] continue=true Dialplan: day of week[3] =~ 2-6 (PASS) Dialplan: hour[15] =~ 9-18 (PASS) Dialplan: sofia/internal/1000@nshplpbx1.unix Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(open=true) Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [global-intercept] destination_number(1008) =~ /^886$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [group-intercept] destination_number(1008) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [intercept-ext] destination_number(1008) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->redial] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [redial] destination_number(1008) =~ /^870$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->global] continue=true Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/internal/1000@nshplpbx1.unix Absolute Condition [global] Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [snom-demo-2] destination_number(1008) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [snom-demo-1] destination_number(1008) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [eavesdrop] destination_number(1008) =~ /^88(.*)$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [eavesdrop] destination_number(1008) =~ /^779$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->call_return] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [call_return] destination_number(1008) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->del-group] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [del-group] destination_number(1008) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->add-group] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [add-group] destination_number(1008) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [call-group-simo] destination_number(1008) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [call-group-order] destination_number(1008) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (FAIL) [extension-intercom] destination_number(1008) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1000@nshplpbx1.unix Regex (PASS) [Local_Extension] destination_number(1008) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(dialed_extension=1008) Dialplan: sofia/internal/1000@nshplpbx1.unix Action export(dialed_extension=1008) Dialplan: sofia/internal/1000@nshplpbx1.unix Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1000@nshplpbx1.unix Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: sofia/internal/1000@nshplpbx1.unix Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(ringback=${us-ring}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(call_timeout=30) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(continue_on_fail=true) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1000@nshplpbx1.unix Action answer() Dialplan: sofia/internal/1000@nshplpbx1.unix Action sleep(1000) Dialplan: sofia/internal/1000@nshplpbx1.unix Action voicemail(default ${domain_name} ${dialed_extension}) 2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:114 (sofia/internal/1000@nshplpbx1.unix) State Change CS_ROUTING -> CS_EXECUTE 2009-11-03 15:39:50.801914 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1000@nshplpbx1.unix) State ROUTING going to sleep 2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_EXECUTE 2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:340 (sofia/internal/1000@nshplpbx1.unix) State EXECUTE 2009-11-03 15:39:50.801914 [DEBUG] mod_sofia.c:173 sofia/internal/1000@nshplpbx1.unix SOFIA EXECUTE 2009-11-03 15:39:50.801914 [DEBUG] switch_core_state_machine.c:151 sofia/internal/1000@nshplpbx1.unix Standard EXECUTE EXECUTE sofia/internal/1000@nshplpbx1.unix set(open=true) 2009-11-03 15:39:50.803724 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [open]=[true] EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-spymap/1000/8c133ad4-67cf-4ffa-8655-56ffa0e3933d) EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-last_dial/1000/1008) EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-last_dial/global/8c133ad4-67cf-4ffa-8655-56ffa0e3933d) EXECUTE sofia/internal/1000@nshplpbx1.unix set(dialed_extension=1008) 2009-11-03 15:39:50.803724 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [dialed_extension]=[1008] EXECUTE sofia/internal/1000@nshplpbx1.unix export(dialed_extension=1008) 2009-11-03 15:39:50.803724 [DEBUG] mod_dptools.c:846 EXPORT [dialed_extension]=[1008] EXECUTE sofia/internal/1000@nshplpbx1.unix bind_meta_app(1 b s execute_extension::dx XML features) 2009-11-03 15:39:50.804911 [INFO] switch_ivr_async.c:2151 Bound B-Leg: 1 execute_extension::dx XML features EXECUTE sofia/internal/1000@nshplpbx1.unix bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1000.2009-11-03-15-39-50.wav) 2009-11-03 15:39:50.804911 [INFO] switch_ivr_async.c:2151 Bound B-Leg: 2 record_session::/usr/local/freeswitch/recordings/1000.2009-11-03-15-39-50.wav EXECUTE sofia/internal/1000@nshplpbx1.unix bind_meta_app(3 b s execute_extension::cf XML features) 2009-11-03 15:39:50.804911 [INFO] switch_ivr_async.c:2151 Bound B-Leg: 3 execute_extension::cf XML features EXECUTE sofia/internal/1000@nshplpbx1.unix set(ringback=%(2000,4000,440.0,480.0)) 2009-11-03 15:39:50.804911 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [ringback]=[%(2000,4000,440.0,480.0)] EXECUTE sofia/internal/1000@nshplpbx1.unix set(transfer_ringback=local_stream://moh) 2009-11-03 15:39:50.804911 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1000@nshplpbx1.unix set(call_timeout=30) 2009-11-03 15:39:50.804911 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [call_timeout]=[30] EXECUTE sofia/internal/1000@nshplpbx1.unix set(hangup_after_bridge=true) 2009-11-03 15:39:50.806131 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1000@nshplpbx1.unix set(continue_on_fail=true) 2009-11-03 15:39:50.806131 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [continue_on_fail]=[true] EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-call_return/1008/1000) EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-last_dial_ext/1008/8c133ad4-67cf-4ffa-8655-56ffa0e3933d) EXECUTE sofia/internal/1000@nshplpbx1.unix set(called_party_callgroup=techsupport) 2009-11-03 15:39:50.806131 [DEBUG] mod_dptools.c:763 sofia/internal/1000@nshplpbx1.unix SET [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1000@nshplpbx1.unix hash(insert/10.85.0.53-last_dial/techsupport/8c133ad4-67cf-4ffa-8655-56ffa0e3933d) EXECUTE sofia/internal/1000@nshplpbx1.unix bridge(user/1008@10.85.0.53) 2009-11-03 15:39:50.812162 [DEBUG] switch_ivr_originate.c:1333 variable string 0 = [presence_id=1008@10.85.0.53] 2009-11-03 15:39:50.812162 [NOTICE] switch_channel.c:613 New Channel sofia/internal/sip:1008@10.86.11.50:5060 [32661f42-b0a9-4179-867d-156b46ae71ce] 2009-11-03 15:39:50.812162 [DEBUG] mod_sofia.c:3061 (sofia/internal/sip:1008@10.86.11.50:5060) State Change CS_NEW -> CS_INIT 2009-11-03 15:39:50.812162 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.812162 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/sip:1008@10.86.11.50:5060) Running State Change CS_INIT 2009-11-03 15:39:50.812162 [DEBUG] switch_core_state_machine.c:330 (sofia/internal/sip:1008@10.86.11.50:5060) State INIT 2009-11-03 15:39:50.812162 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1008@10.86.11.50:5060 SOFIA INIT 2009-11-03 15:39:50.812162 [DEBUG] sofia_glue.c:1761 sip:1008@10.86.11.50:51061;user=phone;transport=udp Setting proxy route to sofia/internal/sip:1008@10.86.11.50:5060 2009-11-03 15:39:50.814226 [DEBUG] mod_sofia.c:111 (sofia/internal/sip:1008@10.86.11.50:5060) State Change CS_INIT -> CS_ROUTING 2009-11-03 15:39:50.814226 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.814226 [DEBUG] sofia.c:3588 Channel sofia/internal/sip:1008@10.86.11.50:5060 entering state [calling][0] 2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:330 (sofia/internal/sip:1008@10.86.11.50:5060) State INIT going to sleep 2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/sip:1008@10.86.11.50:5060) Running State Change CS_ROUTING 2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/sip:1008@10.86.11.50:5060) State ROUTING 2009-11-03 15:39:50.814226 [DEBUG] mod_sofia.c:130 sofia/internal/sip:1008@10.86.11.50:5060 SOFIA ROUTING 2009-11-03 15:39:50.814226 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1008@10.86.11.50:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2009-11-03 15:39:50.814226 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/sip:1008@10.86.11.50:5060) State ROUTING going to sleep 2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/sip:1008@10.86.11.50:5060) Running State Change CS_CONSUME_MEDIA 2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:352 (sofia/internal/sip:1008@10.86.11.50:5060) State CONSUME_MEDIA 2009-11-03 15:39:50.814226 [DEBUG] switch_core_state_machine.c:352 (sofia/internal/sip:1008@10.86.11.50:5060) State CONSUME_MEDIA going to sleep 2009-11-03 15:39:50.817484 [DEBUG] sofia.c:3588 Channel sofia/internal/sip:1008@10.86.11.50:5060 entering state [terminated][503] 2009-11-03 15:39:50.817484 [NOTICE] sofia.c:4187 Hangup sofia/internal/sip:1008@10.86.11.50:5060 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2009-11-03 15:39:50.817484 [DEBUG] switch_channel.c:1896 Send signal sofia/internal/sip:1008@10.86.11.50:5060 [KILL] 2009-11-03 15:39:50.817484 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.817484 [DEBUG] switch_core_state_machine.c:451 thread mismatch skipping state handler. 2009-11-03 15:39:50.817484 [DEBUG] switch_ivr_originate.c:2543 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE] 2009-11-03 15:39:50.817484 [ERR] switch_ivr_originate.c:1829 Cannot create outgoing channel of type [user] cause: [NORMAL_TEMPORARY_FAILURE] 2009-11-03 15:39:50.817484 [DEBUG] switch_ivr_originate.c:2543 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE] 2009-11-03 15:39:50.817484 [INFO] mod_dptools.c:2290 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE 2009-11-03 15:39:50.817484 [DEBUG] mod_dptools.c:2312 Continue on fail [true]: Cause: NORMAL_TEMPORARY_FAILURE EXECUTE sofia/internal/1000@nshplpbx1.unix answer() 2009-11-03 15:39:50.817484 [DEBUG] mod_dptools.c:653 sofia/internal/1000@nshplpbx1.unix receive message [ANSWER] 2009-11-03 15:39:50.817484 [DEBUG] sofia_glue.c:2336 AUDIO RTP [sofia/internal/1000@nshplpbx1.unix] 10.85.0.53 port 24712 -> 10.86.10.58 port 37250 codec: 0 ms: 20 2009-11-03 15:39:50.817484 [DEBUG] switch_rtp.c:1155 Starting timer [soft] 160 bytes per 20ms 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/sip:1008@10.86.11.50:5060) Running State Change CS_HANGUP 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/sip:1008@10.86.11.50:5060) State HANGUP 2009-11-03 15:39:50.818924 [DEBUG] mod_sofia.c:329 sofia/internal/sip:1008@10.86.11.50:5060 Overriding SIP cause 503 with 503 from the other leg 2009-11-03 15:39:50.818924 [DEBUG] mod_sofia.c:361 Channel sofia/internal/sip:1008@10.86.11.50:5060 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:46 sofia/internal/sip:1008@10.86.11.50:5060 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/sip:1008@10.86.11.50:5060) State HANGUP going to sleep 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/sip:1008@10.86.11.50:5060) State Change CS_HANGUP -> CS_REPORTING 2009-11-03 15:39:50.818924 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/sip:1008@10.86.11.50:5060) Running State Change CS_REPORTING 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/sip:1008@10.86.11.50:5060) State REPORTING 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:1008@10.86.11.50:5060 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/sip:1008@10.86.11.50:5060) State REPORTING going to sleep 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:319 (sofia/internal/sip:1008@10.86.11.50:5060) State Change CS_REPORTING -> CS_DESTROY 2009-11-03 15:39:50.818924 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1008@10.86.11.50:5060 [BREAK] 2009-11-03 15:39:50.818924 [DEBUG] switch_core_session.c:1140 Session 32 (sofia/internal/sip:1008@10.86.11.50:5060) Locked, Waiting on external entities 2009-11-03 15:39:50.818924 [NOTICE] switch_core_session.c:1158 Session 32 (sofia/internal/sip:1008@10.86.11.50:5060) Ended 2009-11-03 15:39:50.818924 [NOTICE] switch_core_session.c:1160 Close Channel sofia/internal/sip:1008@10.86.11.50:5060 [CS_DESTROY] 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1008@10.86.11.50:5060) Running State Change CS_DESTROY 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:426 (sofia/internal/sip:1008@10.86.11.50:5060) State DESTROY 2009-11-03 15:39:50.818924 [DEBUG] mod_sofia.c:278 sofia/internal/sip:1008@10.86.11.50:5060 SOFIA DESTROY 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:1008@10.86.11.50:5060 Standard DESTROY 2009-11-03 15:39:50.818924 [DEBUG] switch_core_state_machine.c:426 (sofia/internal/sip:1008@10.86.11.50:5060) State DESTROY going to sleep 2009-11-03 15:39:50.820304 [DEBUG] mod_sofia.c:569 Local SDP sofia/internal/1000@nshplpbx1.unix: v=0 o=FreeSWITCH 1257259678 1257259679 IN IP4 10.85.0.53 s=FreeSWITCH c=IN IP4 10.85.0.53 t=0 0 m=audio 24712 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2009-11-03 15:39:50.821960 [DEBUG] sofia.c:3588 Channel sofia/internal/1000@nshplpbx1.unix entering state [completed][200] 2009-11-03 15:39:50.821960 [DEBUG] switch_core_session.c:664 Send signal sofia/internal/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:50.821960 [NOTICE] mod_dptools.c:653 Channel [sofia/internal/1000@nshplpbx1.unix] has been answered 2009-11-03 15:39:50.821960 [DEBUG] switch_channel.c:182 sofia/internal/1000@nshplpbx1.unix receive message [AUDIO_SYNC] EXECUTE sofia/internal/1000@nshplpbx1.unix sleep(1000) 2009-11-03 15:39:50.821960 [DEBUG] switch_channel.c:182 sofia/internal/1000@nshplpbx1.unix receive message [AUDIO_SYNC] 2009-11-03 15:39:50.867612 [DEBUG] switch_rtp.c:1917 Correct ip/port confirmed. 2009-11-03 15:39:50.926503 [DEBUG] sofia.c:3588 Channel sofia/internal/1000@nshplpbx1.unix entering state [ready][200] EXECUTE sofia/internal/1000@nshplpbx1.unix voicemail(default 10.85.0.53 1008) 2009-11-03 15:39:51.840356 [DEBUG] mod_voicemail.c:799 [default] rwlock 2009-11-03 15:39:51.840356 [DEBUG] switch_channel.c:182 sofia/internal/1000@nshplpbx1.unix receive message [AUDIO_SYNC] 2009-11-03 15:39:51.959567 [DEBUG] switch_ivr_play_say.c:118 No language specified - Using [en] 2009-11-03 15:39:51.961607 [DEBUG] switch_ivr_play_say.c:273 Handle play-file:[voicemail/vm-person.wav] (en:en) 2009-11-03 15:39:51.961607 [DEBUG] switch_ivr_play_say.c:1136 Codec Activated L16@8000hz 1 channels 20ms 2009-11-03 15:39:51.961607 [DEBUG] switch_core_io.c:660 sofia/internal/1000@nshplpbx1.unix receive message [TRANSCODING_NECESSARY] 2009-11-03 15:39:53.319706 [DEBUG] switch_ivr_play_say.c:1428 done playing file 2009-11-03 15:39:53.439693 [DEBUG] switch_ivr_play_say.c:273 Handle say:[1008] (en:en) 2009-11-03 15:39:53.439693 [DEBUG] switch_ivr_play_say.c:1136 Codec Activated L16@8000hz 1 channels 20ms 2009-11-03 15:39:53.439693 [DEBUG] switch_core_io.c:660 sofia/internal/1000@nshplpbx1.unix receive message [TRANSCODING_NECESSARY] 2009-11-03 15:39:53.899622 [DEBUG] switch_ivr_play_say.c:1428 done playing file 2009-11-03 15:39:53.899622 [DEBUG] switch_ivr_play_say.c:1136 Codec Activated L16@8000hz 1 channels 20ms 2009-11-03 15:39:53.899622 [DEBUG] switch_core_io.c:660 sofia/internal/1000@nshplpbx1.unix receive message [TRANSCODING_NECESSARY] 2009-11-03 15:39:54.127652 [NOTICE] sofia.c:328 Hangup sofia/internal/1000@nshplpbx1.unix [CS_EXECUTE] [NORMAL_CLEARING] 2009-11-03 15:39:54.127652 [DEBUG] switch_channel.c:1896 Send signal sofia/internal/1000@nshplpbx1.unix [KILL] 2009-11-03 15:39:54.127652 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:54.127652 [DEBUG] switch_core_state_machine.c:451 thread mismatch skipping state handler. 2009-11-03 15:39:54.139706 [DEBUG] switch_ivr_play_say.c:1428 done playing file 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:340 (sofia/internal/1000@nshplpbx1.unix) State EXECUTE going to sleep 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_HANGUP 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1000@nshplpbx1.unix) State HANGUP 2009-11-03 15:39:54.239929 [DEBUG] mod_sofia.c:329 sofia/internal/1000@nshplpbx1.unix Overriding SIP cause 480 with 503 from the other leg 2009-11-03 15:39:54.239929 [DEBUG] mod_sofia.c:361 Channel sofia/internal/1000@nshplpbx1.unix hanging up, cause: NORMAL_CLEARING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1000@nshplpbx1.unix Standard HANGUP, cause: NORMAL_CLEARING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1000@nshplpbx1.unix) State HANGUP going to sleep 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1000@nshplpbx1.unix) State Change CS_HANGUP -> CS_REPORTING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:306 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_REPORTING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/1000@nshplpbx1.unix) State REPORTING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1000@nshplpbx1.unix Standard REPORTING, cause: NORMAL_CLEARING 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/1000@nshplpbx1.unix) State REPORTING going to sleep 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:319 (sofia/internal/1000@nshplpbx1.unix) State Change CS_REPORTING -> CS_DESTROY 2009-11-03 15:39:54.239929 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1000@nshplpbx1.unix [BREAK] 2009-11-03 15:39:54.239929 [DEBUG] switch_core_session.c:1140 Session 31 (sofia/internal/1000@nshplpbx1.unix) Locked, Waiting on external entities 2009-11-03 15:39:54.239929 [NOTICE] switch_core_session.c:1158 Session 31 (sofia/internal/1000@nshplpbx1.unix) Ended 2009-11-03 15:39:54.239929 [NOTICE] switch_core_session.c:1160 Close Channel sofia/internal/1000@nshplpbx1.unix [CS_DESTROY] 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@nshplpbx1.unix) Running State Change CS_DESTROY 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:426 (sofia/internal/1000@nshplpbx1.unix) State DESTROY 2009-11-03 15:39:54.239929 [DEBUG] mod_sofia.c:278 sofia/internal/1000@nshplpbx1.unix SOFIA DESTROY 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@nshplpbx1.unix Standard DESTROY 2009-11-03 15:39:54.239929 [DEBUG] switch_core_state_machine.c:426 (sofia/internal/1000@nshplpbx1.unix) State DESTROY going to sleep ]0;root@NSHPLPBX1:/usr/local/freeswitch/log[root@NSHPLPBX1 log]#