INCOMING ----------- 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:362 (sofia/external/07867429523@10.20.3.22) Running State Change CS_NEW 2012-11-14 10:11:51.239365 [DEBUG] sofia_glue.c:4767 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000] 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:380 (sofia/external/07867429523@10.20.3.22) State NEW 2012-11-14 10:11:51.239365 [DEBUG] sofia_glue.c:2888 Set Codec sofia/external/07867429523@10.20.3.22 PCMA/8000 20 ms 160 samples 64000 bits 2012-11-14 10:11:51.239365 [DEBUG] sofia_glue.c:4899 No 2833 in SDP. Disable 2833 dtmf and switch to INFO 2012-11-14 10:11:51.239365 [DEBUG] sofia.c:5594 (sofia/external/07867429523@10.20.3.22) State Change CS_NEW -> CS_INIT 2012-11-14 10:11:51.239365 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/07867429523@10.20.3.22 [BREAK] 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:362 (sofia/external/07867429523@10.20.3.22) Running State Change CS_INIT 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:401 (sofia/external/07867429523@10.20.3.22) State INIT 2012-11-14 10:11:51.239365 [DEBUG] mod_sofia.c:85 sofia/external/07867429523@10.20.3.22 SOFIA INIT 2012-11-14 10:11:51.239365 [DEBUG] mod_sofia.c:125 (sofia/external/07867429523@10.20.3.22) State Change CS_INIT -> CS_ROUTING 2012-11-14 10:11:51.239365 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/07867429523@10.20.3.22 [BREAK] 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:401 (sofia/external/07867429523@10.20.3.22) State INIT going to sleep 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:362 (sofia/external/07867429523@10.20.3.22) Running State Change CS_ROUTING 2012-11-14 10:11:51.239365 [DEBUG] switch_channel.c:1884 (sofia/external/07867429523@10.20.3.22) Callstate Change DOWN -> RINGING 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:410 (sofia/external/07867429523@10.20.3.22) State ROUTING 2012-11-14 10:11:51.239365 [DEBUG] mod_sofia.c:148 sofia/external/07867429523@10.20.3.22 SOFIA ROUTING 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:104 sofia/external/07867429523@10.20.3.22 Standard ROUTING 2012-11-14 10:11:51.239365 [INFO] mod_dialplan_xml.c:481 Processing 07867429523 <07867429523>->447574745125 in context external Dialplan: sofia/external/07867429523@10.20.3.22 parsing [external->unloop] continue=false Dialplan: sofia/external/07867429523@10.20.3.22 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/07867429523@10.20.3.22 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/07867429523@10.20.3.22 parsing [external->origin] continue=true Dialplan: sofia/external/07867429523@10.20.3.22 Absolute Condition [origin] Dialplan: sofia/external/07867429523@10.20.3.22 Action set(inter_domain=true) Dialplan: sofia/external/07867429523@10.20.3.22 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/07867429523@10.20.3.22 parsing [external->normalise_number] continue=false Dialplan: sofia/external/07867429523@10.20.3.22 Regex (PASS) [normalise_number] destination_number(447574745125) =~ /^0|0044|\+?44(\d\d+)$/ break=on-false Dialplan: sofia/external/07867429523@10.20.3.22 Action transfer(447574745125 XML default) 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:154 (sofia/external/07867429523@10.20.3.22) State Change CS_ROUTING -> CS_EXECUTE 2012-11-14 10:11:51.239365 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/07867429523@10.20.3.22 [BREAK] 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:410 (sofia/external/07867429523@10.20.3.22) State ROUTING going to sleep 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:362 (sofia/external/07867429523@10.20.3.22) Running State Change CS_EXECUTE 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:417 (sofia/external/07867429523@10.20.3.22) State EXECUTE 2012-11-14 10:11:51.239365 [DEBUG] mod_sofia.c:241 sofia/external/07867429523@10.20.3.22 SOFIA EXECUTE 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:192 sofia/external/07867429523@10.20.3.22 Standard EXECUTE EXECUTE sofia/external/07867429523@10.20.3.22 set(inter_domain=true) 2012-11-14 10:11:51.239365 [DEBUG] mod_dptools.c:1263 sofia/external/07867429523@10.20.3.22 SET [inter_domain]=[true] EXECUTE sofia/external/07867429523@10.20.3.22 set(RFC2822_DATE=Wed, 14 Nov 2012 10:11:51 +0000) 2012-11-14 10:11:51.239365 [DEBUG] mod_dptools.c:1263 sofia/external/07867429523@10.20.3.22 SET [RFC2822_DATE]=[Wed, 14 Nov 2012 10:11:51 +0000] EXECUTE sofia/external/07867429523@10.20.3.22 transfer(447574745125 XML default) 2012-11-14 10:11:51.239365 [DEBUG] switch_ivr.c:1705 (sofia/external/07867429523@10.20.3.22) State Change CS_EXECUTE -> CS_ROUTING 2012-11-14 10:11:51.239365 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/07867429523@10.20.3.22 [BREAK] 2012-11-14 10:11:51.239365 [DEBUG] switch_core_session.c:729 Send signal sofia/external/07867429523@10.20.3.22 [BREAK] 2012-11-14 10:11:51.239365 [NOTICE] switch_ivr.c:1711 Transfer sofia/external/07867429523@10.20.3.22 to XML[447574745125@default] 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:417 (sofia/external/07867429523@10.20.3.22) State EXECUTE going to sleep 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:362 (sofia/external/07867429523@10.20.3.22) Running State Change CS_ROUTING 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:410 (sofia/external/07867429523@10.20.3.22) State ROUTING 2012-11-14 10:11:51.239365 [DEBUG] mod_sofia.c:148 sofia/external/07867429523@10.20.3.22 SOFIA ROUTING 2012-11-14 10:11:51.239365 [DEBUG] switch_core_state_machine.c:104 sofia/external/07867429523@10.20.3.22 Standard ROUTING 2012-11-14 10:11:51.239365 [INFO] mod_dialplan_xml.c:481 Processing 07867429523 <07867429523>->447574745125 in context default Dialplan: sofia/external/07867429523@10.20.3.22 parsing [default->unloop] continue=false Dialplan: sofia/external/07867429523@10.20.3.22 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/07867429523@10.20.3.22 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/07867429523@10.20.3.22 parsing [default->num_lookup] continue=true Dialplan: sofia/external/07867429523@10.20.3.22 Regex (PASS) [num_lookup] destination_number(447574745125) =~ /^(\d+)$/ break=on-false Dialplan: sofia/external/07867429523@10.20.3.22 Action set(dialed_extension=447574745125) Dialplan: sofia/external/07867429523@10.20.3.22 Action export(dialed_extension=447574745125) Dialplan: sofia/external/07867429523@10.20.3.22 Action lua(num_lookup.lua 447574745125 ${domain_name}) INLINE EXECUTE sofia/external/07867429523@10.20.3.22 lua(num_lookup.lua 447574745125 80.74.227.100) 2012-11-14 10:11:51.249363 [DEBUG] switch_cpp.cpp:1007 sofia/external/07867429523@10.20.3.22 destroy/unlink session from object Dialplan: sofia/external/07867429523@10.20.3.22 parsing [default->uk01_extension] continue=false Dialplan: sofia/external/07867429523@10.20.3.22 Regex (PASS) [uk01_extension] ${svc_type}(extn) =~ /^extn$/ break=on-false Dialplan: sofia/external/07867429523@10.20.3.22 Regex (PASS) [uk01_extension] destination_number(447574745125) =~ /^(\d+)$/ break=on-false Dialplan: sofia/external/07867429523@10.20.3.22 Action set(ringback=${uk-ring}) Dialplan: sofia/external/07867429523@10.20.3.22 Action set(hangup_after_bridge=true) Dialplan: sofia/external/07867429523@10.20.3.22 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/external/07867429523@10.20.3.22 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/external/07867429523@10.20.3.22 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/external/07867429523@10.20.3.22 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/external/07867429523@10.20.3.22 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/external/07867429523@10.20.3.22 Action lua(num_lookup.lua 447574745125 ${domain_name}) INLINE EXECUTE sofia/external/07867429523@10.20.3.22 lua(num_lookup.lua 447574745125 vectone.uk01.net) 2012-11-14 10:11:51.249363 [DEBUG] switch_cpp.cpp:1007 sofia/external/07867429523@10.20.3.22 destroy/unlink session from object Dialplan: sofia/external/07867429523@10.20.3.22 Action bridge(user/${user_id}@${domain_name}) Dialplan: sofia/external/07867429523@10.20.3.22 Action answer() Dialplan: sofia/external/07867429523@10.20.3.22 Action sleep(1000) Dialplan: sofia/external/07867429523@10.20.3.22 Action voicemail(default ${domain_name} ${user_id}) 2012-11-14 10:11:51.249363 [DEBUG] switch_core_state_machine.c:154 (sofia/external/07867429523@10.20.3.22) State Change CS_ROUTING -> CS_EXECUTE 2012-11-14 10:11:51.249363 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/07867429523@10.20.3.22 [BREAK] 2012-11-14 10:11:51.249363 [DEBUG] switch_core_state_machine.c:410 (sofia/external/07867429523@10.20.3.22) State ROUTING going to sleep 2012-11-14 10:11:51.249363 [DEBUG] switch_core_state_machine.c:362 (sofia/external/07867429523@10.20.3.22) Running State Change CS_EXECUTE 2012-11-14 10:11:51.249363 [DEBUG] switch_core_state_machine.c:417 (sofia/external/07867429523@10.20.3.22) State EXECUTE 2012-11-14 10:11:51.249363 [DEBUG] mod_sofia.c:241 sofia/external/07867429523@10.20.3.22 SOFIA EXECUTE 2012-11-14 10:11:51.249363 [DEBUG] switch_core_state_machine.c:192 sofia/external/07867429523@10.20.3.22 Standard EXECUTE EXECUTE sofia/external/07867429523@10.20.3.22 set(dialed_extension=447574745125) 2012-11-14 10:11:51.249363 [DEBUG] mod_dptools.c:1263 sofia/external/07867429523@10.20.3.22 SET [dialed_extension]=[447574745125] EXECUTE sofia/external/07867429523@10.20.3.22 export(dialed_extension=447574745125) 2012-11-14 10:11:51.249363 [DEBUG] switch_channel.c:1091 EXPORT (export_vars) [dialed_extension]=[447574745125] EXECUTE sofia/external/07867429523@10.20.3.22 set(ringback=%(400,200,400,450);%(400,2200,400,450)) 2012-11-14 10:11:51.249363 [DEBUG] mod_dptools.c:1263 sofia/external/07867429523@10.20.3.22 SET [ringback]=[%(400,200,400,450);%(400,2200,400,450)] EXECUTE sofia/external/07867429523@10.20.3.22 set(hangup_after_bridge=true) 2012-11-14 10:11:51.249363 [DEBUG] mod_dptools.c:1263 sofia/external/07867429523@10.20.3.22 SET [hangup_after_bridge]=[true] 2012-11-14 10:11:51.259369 [DEBUG] switch_cpp.cpp:1227 directory.lua - generated XML:
EXECUTE sofia/external/07867429523@10.20.3.22 set(called_party_callgroup=) 2012-11-14 10:11:51.259369 [DEBUG] mod_dptools.c:1263 sofia/external/07867429523@10.20.3.22 SET [called_party_callgroup]=[UNDEF] EXECUTE sofia/external/07867429523@10.20.3.22 hash(insert/vectone.uk01.net-call_return/447574745125/07867429523) EXECUTE sofia/external/07867429523@10.20.3.22 hash(insert/vectone.uk01.net-last_dial_ext/447574745125/b5358b84-2e43-11e2-93c6-27031b846552) EXECUTE sofia/external/07867429523@10.20.3.22 hash(insert/vectone.uk01.net-last_dial_ext//b5358b84-2e43-11e2-93c6-27031b846552) EXECUTE sofia/external/07867429523@10.20.3.22 hash(insert/vectone.uk01.net-last_dial_ext/global/b5358b84-2e43-11e2-93c6-27031b846552) EXECUTE sofia/external/07867429523@10.20.3.22 bridge(user/250@vectone.uk01.net) 2012-11-14 10:11:51.259369 [DEBUG] switch_channel.c:1045 sofia/external/07867429523@10.20.3.22 EXPORTING[export_vars] [dialed_extension]=[447574745125] to event 2012-11-14 10:11:51.259369 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-11-14 10:11:51.259369 [DEBUG] switch_cpp.cpp:1227 directory.lua - generated XML:
2012-11-14 10:11:51.259369 [DEBUG] switch_channel.c:1045 sofia/external/07867429523@10.20.3.22 EXPORTING[export_vars] [dialed_extension]=[447574745125] to event 2012-11-14 10:11:51.259369 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-11-14 10:11:51.259369 [DEBUG] switch_event.c:1521 Parsing variable [sip_invite_domain]=[vectone.uk01.net] 2012-11-14 10:11:51.259369 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[250@vectone.uk01.net] 2012-11-14 10:11:51.259369 [DEBUG] switch_ivr_originate.c:2299 Parsing session specific variables 2012-11-14 10:11:51.259369 [DEBUG] switch_event.c:1521 Parsing variable [leg_delay_start]=[7] 2012-11-14 10:11:51.259369 [NOTICE] switch_channel.c:924 New Channel sofia/internal/sip:250@192.168.2.48:5060 [b539cffa-2e43-11e2-93cd-27031b846552] 2012-11-14 10:11:51.259369 [DEBUG] mod_sofia.c:4596 (sofia/internal/sip:250@192.168.2.48:5060) State Change CS_NEW -> CS_INIT 2012-11-14 10:11:51.259369 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:250@192.168.2.48:5060 [BREAK] 2012-11-14 10:11:51.259369 [DEBUG] switch_ivr_originate.c:2579 sofia/internal/sip:250@192.168.2.48:5060 Setting leg delay start to 7 2012-11-14 10:11:51.259369 [NOTICE] switch_channel.c:924 New Channel sofia/internal/1001447574745125@10.20.3.16 [b539e648-2e43-11e2-93d2-27031b846552] 2012-11-14 10:11:51.259369 [DEBUG] mod_sofia.c:4596 (sofia/internal/1001447574745125@10.20.3.16) State Change CS_NEW -> CS_INIT 2012-11-14 10:11:51.259369 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/1001447574745125@10.20.3.16 [BREAK] 2012-11-14 10:11:51.269413 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/1001447574745125@10.20.3.16) Running State Change CS_INIT 2012-11-14 10:11:51.269413 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/1001447574745125@10.20.3.16) State INIT 2012-11-14 10:11:51.269413 [DEBUG] mod_sofia.c:85 sofia/internal/1001447574745125@10.20.3.16 SOFIA INIT 2012-11-14 10:11:51.269413 [DEBUG] mod_sofia.c:125 (sofia/internal/1001447574745125@10.20.3.16) State Change CS_INIT -> CS_ROUTING 2012-11-14 10:11:51.269413 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/1001447574745125@10.20.3.16 [BREAK] 2012-11-14 10:11:51.269413 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/1001447574745125@10.20.3.16) State INIT going to sleep 2012-11-14 10:11:51.269413 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/1001447574745125@10.20.3.16) Running State Change CS_ROUTING 2012-11-14 10:11:51.269413 [DEBUG] switch_channel.c:1884 (sofia/internal/1001447574745125@10.20.3.16) Callstate Change DOWN -> RINGING 2012-11-14 10:11:51.269413 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/1001447574745125@10.20.3.16 [BREAK] 2012-11-14 10:11:51.269413 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/1001447574745125@10.20.3.16) State ROUTING 2012-11-14 10:11:51.269413 [DEBUG] mod_sofia.c:148 sofia/internal/1001447574745125@10.20.3.16 SOFIA ROUTING 2012-11-14 10:11:51.269413 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/1001447574745125@10.20.3.16) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2012-11-14 10:11:51.269413 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/1001447574745125@10.20.3.16 [BREAK] 2012-11-14 10:11:51.269413 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/1001447574745125@10.20.3.16) State ROUTING going to sleep 2012-11-14 10:11:51.269413 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/1001447574745125@10.20.3.16) Running State Change CS_CONSUME_MEDIA 2012-11-14 10:11:51.269413 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/1001447574745125@10.20.3.16) State CONSUME_MEDIA 2012-11-14 10:11:51.269413 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/1001447574745125@10.20.3.16) State CONSUME_MEDIA going to sleep 2012-11-14 10:11:51.269413 [DEBUG] sofia.c:5371 Channel sofia/internal/1001447574745125@10.20.3.16 entering state [calling][0] 2012-11-14 10:11:51.769365 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/1001447574745125@10.20.3.16 [BREAK] 2012-11-14 10:11:51.769365 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/1001447574745125@10.20.3.16 [BREAK] 2012-11-14 10:11:51.769365 [DEBUG] sofia.c:5371 Channel sofia/internal/1001447574745125@10.20.3.16 entering state [proceeding][180] 2012-11-14 10:11:51.769365 [DEBUG] sofia.c:5382 Remote SDP: v=0 o=- 3561880727 3561880727 IN IP4 10.20.3.22 s=SDP session c=IN IP4 172.31.10.109 t=0 0 m=audio 17828 RTP/AVP 8 a=rtpmap:8 PCMA/8000 2012-11-14 10:11:51.769365 [DEBUG] sofia_glue.c:4767 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000] 2012-11-14 10:11:51.769365 [DEBUG] sofia_glue.c:2888 Set Codec sofia/internal/1001447574745125@10.20.3.16 PCMA/8000 20 ms 160 samples 64000 bits 2012-11-14 10:11:51.769365 [DEBUG] sofia_glue.c:4899 No 2833 in SDP. Disable 2833 dtmf and switch to INFO 2012-11-14 10:11:51.769365 [DEBUG] sofia_glue.c:3140 AUDIO RTP [sofia/internal/1001447574745125@10.20.3.16] 80.74.227.100 port 18596 -> 172.31.10.109 port 17828 codec: 8 ms: 20 2012-11-14 10:11:51.769365 [DEBUG] switch_rtp.c:1642 Starting timer [soft] 160 bytes per 20ms 2012-11-14 10:11:51.769365 [NOTICE] sofia_glue.c:3914 Pre-Answer sofia/internal/1001447574745125@10.20.3.16! 2012-11-14 10:11:51.769365 [DEBUG] switch_channel.c:2930 (sofia/internal/1001447574745125@10.20.3.16) Callstate Change RINGING -> EARLY 2012-11-14 10:11:51.779365 [INFO] switch_ivr_originate.c:1115 Sending early media 2012-11-14 10:11:51.779365 [DEBUG] sofia_glue.c:3140 AUDIO RTP [sofia/external/07867429523@10.20.3.22] 80.74.227.100 port 21794 -> 172.31.10.109 port 17826 codec: 8 ms: 20 2012-11-14 10:11:51.779365 [DEBUG] switch_rtp.c:1642 Starting timer [soft] 160 bytes per 20ms 2012-11-14 10:11:51.779365 [DEBUG] switch_channel.c:2972 Send signal sofia/external/07867429523@10.20.3.22 [BREAK] 2012-11-14 10:11:51.779365 [DEBUG] mod_sofia.c:2544 Ring SDP: v=0 o=FreeSWITCH 1352866117 1352866118 IN IP4 80.74.227.100 s=FreeSWITCH c=IN IP4 80.74.227.100 t=0 0 m=audio 21794 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2012-11-14 10:11:51.779365 [NOTICE] mod_sofia.c:2547 Pre-Answer sofia/external/07867429523@10.20.3.22! 2012-11-14 10:11:51.779365 [DEBUG] switch_channel.c:2930 (sofia/external/07867429523@10.20.3.22) Callstate Change RINGING -> EARLY 2012-11-14 10:11:51.779365 [DEBUG] switch_core_session.c:729 Send signal sofia/external/07867429523@10.20.3.22 [BREAK] 2012-11-14 10:11:51.779365 [DEBUG] switch_ivr_originate.c:1164 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2012-11-14 10:11:51.779365 [DEBUG] switch_core_codec.c:116 sofia/external/07867429523@10.20.3.22 Push codec L16:70 2012-11-14 10:11:51.779365 [DEBUG] switch_ivr_originate.c:1227 Play Ringback Tone [%(400,200,400,450);%(400,2200,400,450)] 2012-11-14 10:11:51.779365 [DEBUG] switch_core_session.c:875 Send signal sofia/external/07867429523@10.20.3.22 [BREAK] 2012-11-14 10:11:51.779365 [DEBUG] sofia.c:5364 Channel sofia/external/07867429523@10.20.3.22 skipping state [early][183] 2012-11-14 10:11:51.839365 [DEBUG] switch_rtp.c:3187 Correct ip/port confirmed. ====================================================================================================================================================== OUTGOING -------- 2012-11-14 10:16:58.239366 [DEBUG] switch_core_state_machine.c:362 (sofia/mo-internal/447574745125@10.20.3.22) Running State Change CS_NEW 2012-11-14 10:16:58.239366 [DEBUG] switch_core_state_machine.c:380 (sofia/mo-internal/447574745125@10.20.3.22) State NEW 2012-11-14 10:16:58.239366 [DEBUG] sofia.c:5574 (sofia/mo-internal/447574745125@10.20.3.22) State Change CS_NEW -> CS_INIT 2012-11-14 10:16:58.239366 [DEBUG] switch_core_session.c:1180 Send signal sofia/mo-internal/447574745125@10.20.3.22 [BREAK] 2012-11-14 10:16:58.239366 [DEBUG] switch_core_state_machine.c:362 (sofia/mo-internal/447574745125@10.20.3.22) Running State Change CS_INIT 2012-11-14 10:16:58.239366 [DEBUG] switch_core_state_machine.c:401 (sofia/mo-internal/447574745125@10.20.3.22) State INIT 2012-11-14 10:16:58.239366 [DEBUG] mod_sofia.c:85 sofia/mo-internal/447574745125@10.20.3.22 SOFIA INIT 2012-11-14 10:16:58.239366 [DEBUG] mod_sofia.c:125 (sofia/mo-internal/447574745125@10.20.3.22) State Change CS_INIT -> CS_ROUTING 2012-11-14 10:16:58.239366 [DEBUG] switch_core_session.c:1180 Send signal sofia/mo-internal/447574745125@10.20.3.22 [BREAK] 2012-11-14 10:16:58.239366 [DEBUG] switch_core_state_machine.c:401 (sofia/mo-internal/447574745125@10.20.3.22) State INIT going to sleep 2012-11-14 10:16:58.239366 [DEBUG] switch_core_state_machine.c:362 (sofia/mo-internal/447574745125@10.20.3.22) Running State Change CS_ROUTING 2012-11-14 10:16:58.239366 [DEBUG] switch_channel.c:1884 (sofia/mo-internal/447574745125@10.20.3.22) Callstate Change DOWN -> RINGING 2012-11-14 10:16:58.239366 [DEBUG] switch_core_state_machine.c:410 (sofia/mo-internal/447574745125@10.20.3.22) State ROUTING 2012-11-14 10:16:58.239366 [DEBUG] mod_sofia.c:148 sofia/mo-internal/447574745125@10.20.3.22 SOFIA ROUTING 2012-11-14 10:16:58.239366 [DEBUG] switch_core_state_machine.c:104 sofia/mo-internal/447574745125@10.20.3.22 Standard ROUTING 2012-11-14 10:16:58.239366 [INFO] mod_dialplan_xml.c:481 Processing 447574745125 <447574745125>->447867429523 in context mo-internal Dialplan: sofia/mo-internal/447574745125@10.20.3.22 parsing [mo-internal->unloop] continue=false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 parsing [mo-internal->origin] continue=true Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Absolute Condition [origin] Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Action set(intra_domain=true) Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Action lua(msisdn_user.lua) INLINE EXECUTE sofia/mo-internal/447574745125@10.20.3.22 lua(msisdn_user.lua) 2012-11-14 10:16:58.259366 [DEBUG] switch_cpp.cpp:1007 sofia/mo-internal/447574745125@10.20.3.22 destroy/unlink session from object Dialplan: sofia/mo-internal/447574745125@10.20.3.22 parsing [mo-internal->set_user] continue=true Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (PASS) [set_user] ${sip_user_account}(250@vectone.uk01.net) =~ /.+/ break=on-false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Action set_user(${sip_user_account}) Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Action log(NOTICE set_user ${sip_user_account}) Dialplan: sofia/mo-internal/447574745125@10.20.3.22 parsing [mo-internal->auth_exten] continue=false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (FAIL) [auth_exten] ${caller_domain_prefix}() =~ /^001$/ break=on-false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 parsing [mo-internal->Local Mapped DID Calls] continue=false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (PASS) [Local Mapped DID Calls] ${caller_prefix}(001) =~ /.+/ break=on-false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (FAIL) [Local Mapped DID Calls] ${local_did}() =~ /.+/ break=on-false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 parsing [mo-internal->Intra Domain Calls] continue=false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (FAIL) [Intra Domain Calls] ${dest_prefix}() =~ /.+/ break=on-false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 parsing [mo-internal->Offnet Calls] continue=false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (FAIL) [Offnet Calls] ${dest_prefix}() =~ /.+/ break=on-true Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (PASS) [Offnet Calls] ${caller_prefix}(001) =~ /^\d{3,4}$/ break=on-false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Regex (PASS) [Offnet Calls] ${destination_number}(447867429523) =~ /^\d{9,18}$/ break=on-false Dialplan: sofia/mo-internal/447574745125@10.20.3.22 Action bridge(sofia/internal/9990${caller_prefix}${destination_number}@10.20.3.16) 2012-11-14 10:16:58.259366 [DEBUG] switch_core_state_machine.c:154 (sofia/mo-internal/447574745125@10.20.3.22) State Change CS_ROUTING -> CS_EXECUTE 2012-11-14 10:16:58.259366 [DEBUG] switch_core_session.c:1180 Send signal sofia/mo-internal/447574745125@10.20.3.22 [BREAK] 2012-11-14 10:16:58.259366 [DEBUG] switch_core_state_machine.c:410 (sofia/mo-internal/447574745125@10.20.3.22) State ROUTING going to sleep 2012-11-14 10:16:58.259366 [DEBUG] switch_core_state_machine.c:362 (sofia/mo-internal/447574745125@10.20.3.22) Running State Change CS_EXECUTE 2012-11-14 10:16:58.259366 [DEBUG] switch_core_state_machine.c:417 (sofia/mo-internal/447574745125@10.20.3.22) State EXECUTE 2012-11-14 10:16:58.259366 [DEBUG] mod_sofia.c:241 sofia/mo-internal/447574745125@10.20.3.22 SOFIA EXECUTE 2012-11-14 10:16:58.259366 [DEBUG] switch_core_state_machine.c:192 sofia/mo-internal/447574745125@10.20.3.22 Standard EXECUTE EXECUTE sofia/mo-internal/447574745125@10.20.3.22 set(intra_domain=true) 2012-11-14 10:16:58.259366 [DEBUG] mod_dptools.c:1263 sofia/mo-internal/447574745125@10.20.3.22 SET [intra_domain]=[true] EXECUTE sofia/mo-internal/447574745125@10.20.3.22 set(RFC2822_DATE=Wed, 14 Nov 2012 10:16:58 +0000) 2012-11-14 10:16:58.259366 [DEBUG] mod_dptools.c:1263 sofia/mo-internal/447574745125@10.20.3.22 SET [RFC2822_DATE]=[Wed, 14 Nov 2012 10:16:58 +0000] EXECUTE sofia/mo-internal/447574745125@10.20.3.22 set_user(250@vectone.uk01.net) 2012-11-14 10:16:58.259366 [DEBUG] switch_cpp.cpp:1227 directory.lua - generated XML:
EXECUTE sofia/mo-internal/447574745125@10.20.3.22 log(NOTICE set_user 250@vectone.uk01.net) 2012-11-14 10:16:58.259366 [NOTICE] mod_dptools.c:1402 set_user 250@vectone.uk01.net EXECUTE sofia/mo-internal/447574745125@10.20.3.22 bridge(sofia/internal/9990001447867429523@10.20.3.16) 2012-11-14 10:16:58.269369 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-11-14 10:16:58.269369 [NOTICE] switch_channel.c:924 New Channel sofia/internal/9990001447867429523@10.20.3.16 [6c3669a2-2e44-11e2-97bb-27031b846552] 2012-11-14 10:16:58.269369 [DEBUG] mod_sofia.c:4596 (sofia/internal/9990001447867429523@10.20.3.16) State Change CS_NEW -> CS_INIT 2012-11-14 10:16:58.269369 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/9990001447867429523@10.20.3.16 [BREAK] 2012-11-14 10:16:58.269369 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/9990001447867429523@10.20.3.16) Running State Change CS_INIT 2012-11-14 10:16:58.269369 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/9990001447867429523@10.20.3.16) State INIT 2012-11-14 10:16:58.269369 [DEBUG] mod_sofia.c:85 sofia/internal/9990001447867429523@10.20.3.16 SOFIA INIT 2012-11-14 10:16:58.269369 [DEBUG] mod_sofia.c:125 (sofia/internal/9990001447867429523@10.20.3.16) State Change CS_INIT -> CS_ROUTING 2012-11-14 10:16:58.269369 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/9990001447867429523@10.20.3.16 [BREAK] 2012-11-14 10:16:58.269369 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/9990001447867429523@10.20.3.16) State INIT going to sleep 2012-11-14 10:16:58.269369 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/9990001447867429523@10.20.3.16) Running State Change CS_ROUTING 2012-11-14 10:16:58.269369 [DEBUG] switch_channel.c:1884 (sofia/internal/9990001447867429523@10.20.3.16) Callstate Change DOWN -> RINGING 2012-11-14 10:16:58.269369 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/9990001447867429523@10.20.3.16) State ROUTING 2012-11-14 10:16:58.269369 [DEBUG] mod_sofia.c:148 sofia/internal/9990001447867429523@10.20.3.16 SOFIA ROUTING 2012-11-14 10:16:58.269369 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/9990001447867429523@10.20.3.16) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2012-11-14 10:16:58.269369 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/9990001447867429523@10.20.3.16 [BREAK] 2012-11-14 10:16:58.269369 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/9990001447867429523@10.20.3.16) State ROUTING going to sleep 2012-11-14 10:16:58.269369 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/9990001447867429523@10.20.3.16) Running State Change CS_CONSUME_MEDIA 2012-11-14 10:16:58.269369 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/9990001447867429523@10.20.3.16 [BREAK] 2012-11-14 10:16:58.269369 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/9990001447867429523@10.20.3.16) State CONSUME_MEDIA 2012-11-14 10:16:58.269369 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/9990001447867429523@10.20.3.16) State CONSUME_MEDIA going to sleep 2012-11-14 10:16:58.269369 [DEBUG] sofia.c:5371 Channel sofia/internal/9990001447867429523@10.20.3.16 entering state [calling][0] 2012-11-14 10:16:58.279366 [DEBUG] sofia.c:7400 IP 192.168.9.2 Rejected by acl "domains". Falling back to Digest auth.