2013-10-01 17:50:45.290072 [NOTICE] switch_channel.c:978 New Channel sofia/internal/3333320116@sipserver.net [674ea0b0-2aad-11e3-ac3d-434c845291ea]
2013-10-01 17:50:45.290072 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.290072 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.290072 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116@sipserver.net) Running State Change CS_NEW
2013-10-01 17:50:45.290072 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/3333320116@sipserver.net) State NEW
2013-10-01 17:50:45.310083 [DEBUG] sofia.c:7793 IP 193.104.89.45 Approved by acl "localnet.auto[]". Access Granted.
2013-10-01 17:50:45.310083 [DEBUG] sofia.c:5685 Channel sofia/internal/3333320116@sipserver.net entering state [received][100]
2013-10-01 17:50:45.310083 [DEBUG] sofia.c:5696 Remote SDP:
v=0
o=- 243381907 243381907 IN IP4 193.104.89.10
s=-
c=IN IP4 193.104.89.46
t=0 0
m=audio 60794 RTP/AVP 8 0 2 4 18 96 97 98 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729a/8000
a=rtpmap:96 G726-40/8000
a=rtpmap:97 G726-24/8000
a=rtpmap:98 G726-16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2013-10-01 17:50:45.310083 [DEBUG] sofia.c:5909 (sofia/internal/3333320116@sipserver.net) State Change CS_NEW -> CS_INIT
2013-10-01 17:50:45.310083 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116@sipserver.net) Running State Change CS_INIT
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/3333320116@sipserver.net) State INIT
2013-10-01 17:50:45.310083 [DEBUG] mod_sofia.c:87 sofia/internal/3333320116@sipserver.net SOFIA INIT
2013-10-01 17:50:45.310083 [DEBUG] mod_sofia.c:127 (sofia/internal/3333320116@sipserver.net) State Change CS_INIT -> CS_ROUTING
2013-10-01 17:50:45.310083 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/3333320116@sipserver.net) State INIT going to sleep
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116@sipserver.net) Running State Change CS_ROUTING
2013-10-01 17:50:45.310083 [DEBUG] switch_channel.c:2034 (sofia/internal/3333320116@sipserver.net) Callstate Change DOWN -> RINGING
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/3333320116@sipserver.net) State ROUTING
2013-10-01 17:50:45.310083 [DEBUG] mod_sofia.c:150 sofia/internal/3333320116@sipserver.net SOFIA ROUTING
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:117 sofia/internal/3333320116@sipserver.net Standard ROUTING
2013-10-01 17:50:45.310083 [INFO] mod_dialplan_xml.c:557 Processing Callum Guy <3333320116>->7502 in context public
Dialplan: sofia/internal/3333320116@sipserver.net parsing [public->unloop] continue=false
Dialplan: sofia/internal/3333320116@sipserver.net Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/3333320116@sipserver.net Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/3333320116@sipserver.net parsing [public->outside_call] continue=true
Dialplan: sofia/internal/3333320116@sipserver.net Absolute Condition [outside_call]
Dialplan: sofia/internal/3333320116@sipserver.net Action set(outside_call=true)
Dialplan: sofia/internal/3333320116@sipserver.net Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/3333320116@sipserver.net parsing [public->call_debug] continue=true
Dialplan: sofia/internal/3333320116@sipserver.net Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3333320116@sipserver.net parsing [public->public_extensions] continue=false
Dialplan: sofia/internal/3333320116@sipserver.net Regex (FAIL) [public_extensions] destination_number(7502) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/3333320116@sipserver.net parsing [public->public_did] continue=false
Dialplan: sofia/internal/3333320116@sipserver.net Regex (FAIL) [public_did] destination_number(7502) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/internal/3333320116@sipserver.net parsing [public->sendtosocket] continue=false
Dialplan: sofia/internal/3333320116@sipserver.net Regex (PASS) [sendtosocket] destination_number(7502) =~ /^[0-9]{1,15}$/ break=on-false
Dialplan: sofia/internal/3333320116@sipserver.net Action socket(192.168.5.83:8084)
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/3333320116@sipserver.net) State Change CS_ROUTING -> CS_EXECUTE
2013-10-01 17:50:45.310083 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/3333320116@sipserver.net) State ROUTING going to sleep
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116@sipserver.net) Running State Change CS_EXECUTE
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/3333320116@sipserver.net) State EXECUTE
2013-10-01 17:50:45.310083 [DEBUG] mod_sofia.c:243 sofia/internal/3333320116@sipserver.net SOFIA EXECUTE
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:209 sofia/internal/3333320116@sipserver.net Standard EXECUTE
EXECUTE sofia/internal/3333320116@sipserver.net set(outside_call=true)
2013-10-01 17:50:45.310083 [DEBUG] mod_dptools.c:1373 sofia/internal/3333320116@sipserver.net SET [outside_call]=[true]
EXECUTE sofia/internal/3333320116@sipserver.net export(RFC2822_DATE=Tue, 01 Oct 2013 17:50:45 +0100)
2013-10-01 17:50:45.310083 [DEBUG] switch_channel.c:1145 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 01 Oct 2013 17:50:45 +0100]
EXECUTE sofia/internal/3333320116@sipserver.net socket(192.168.5.83:8084)
2013-10-01 17:50:45.340072 [DEBUG] switch_ivr.c:612 sofia/internal/3333320116@sipserver.net Command Execute answer()
EXECUTE sofia/internal/3333320116@sipserver.net answer()
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3119 Set Codec sofia/internal/3333320116@sipserver.net PCMA/8000 20 ms 160 samples 64000 bits
2013-10-01 17:50:45.340072 [DEBUG] switch_core_codec.c:111 sofia/internal/3333320116@sipserver.net Original read codec set to PCMA:8
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:5305 Set 2833 dtmf send/recv payload to 101
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3378 AUDIO RTP [sofia/internal/3333320116@sipserver.net] 193.104.89.37 port 17122 -> 193.104.89.46 port 60794 codec: 8 ms: 20
2013-10-01 17:50:45.340072 [DEBUG] switch_rtp.c:1985 Starting timer [soft] 160 bytes per 20ms
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3642 Set 2833 dtmf send payload to 101
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3648 Set 2833 dtmf receive payload to 101
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3675 sofia/internal/3333320116@sipserver.net Set rtp dtmf delay to 40
2013-10-01 17:50:45.340072 [NOTICE] sofia_glue.c:4286 Pre-Answer sofia/internal/3333320116@sipserver.net!
2013-10-01 17:50:45.340072 [DEBUG] switch_channel.c:3265 (sofia/internal/3333320116@sipserver.net) Callstate Change RINGING -> EARLY
2013-10-01 17:50:45.340072 [DEBUG] mod_sofia.c:864 Local SDP sofia/internal/3333320116@sipserver.net:
v=0
o=FreeSWITCH 1380629123 1380629124 IN IP4 193.104.89.37
s=FreeSWITCH
c=IN IP4 193.104.89.37
t=0 0
m=audio 17122 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2013-10-01 17:50:45.340072 [DEBUG] switch_core_session.c:853 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.340072 [NOTICE] mod_dptools.c:1205 Channel [sofia/internal/3333320116@sipserver.net] has been answered
2013-10-01 17:50:45.340072 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.340072 [DEBUG] switch_channel.c:3542 (sofia/internal/3333320116@sipserver.net) Callstate Change EARLY -> ACTIVE
2013-10-01 17:50:45.340072 [DEBUG] sofia.c:5685 Channel sofia/internal/3333320116@sipserver.net entering state [completed][200]
2013-10-01 17:50:45.340072 [DEBUG] switch_ivr.c:612 sofia/internal/3333320116@sipserver.net Command Execute park()
EXECUTE sofia/internal/3333320116@sipserver.net park()
2013-10-01 17:50:45.370072 [DEBUG] switch_core_session.c:1133 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.380023 [DEBUG] switch_ivr.c:612 sofia/internal/3333320116@sipserver.net Command Execute record(/usr/share/sounds/recordings/test.wav 15 200)
EXECUTE sofia/internal/3333320116@sipserver.net record(/usr/share/sounds/recordings/test.wav 15 200)
2013-10-01 17:50:45.380023 [DEBUG] switch_ivr_play_say.c:599 Raw Codec Activated
2013-10-01 17:50:45.380023 [DEBUG] switch_core_codec.c:219 sofia/internal/3333320116@sipserver.net Push codec L16:70
2013-10-01 17:50:45.390071 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.390071 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.390071 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:45.400072 [DEBUG] sofia.c:5685 Channel sofia/internal/3333320116@sipserver.net entering state [ready][200]
2013-10-01 17:50:48.380081 [DEBUG] switch_core_codec.c:244 sofia/internal/3333320116@sipserver.net Restore previous codec PCMA:8.
2013-10-01 17:50:53.910084 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:53.920072 [NOTICE] sofia.c:716 Hangup sofia/internal/3333320116@sipserver.net [CS_EXECUTE] [NORMAL_CLEARING]
2013-10-01 17:50:53.920072 [DEBUG] switch_channel.c:3096 Send signal sofia/internal/3333320116@sipserver.net [KILL]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:2731 sofia/internal/3333320116@sipserver.net skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-10-01 17:50:53.920072 [DEBUG] switch_ivr.c:650 sofia/internal/3333320116@sipserver.net skip receive message [AUDIO_SYNC] (channel is hungup already)
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:2731 sofia/internal/3333320116@sipserver.net skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/3333320116@sipserver.net) State EXECUTE going to sleep
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116@sipserver.net) Running State Change CS_HANGUP
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:676 (sofia/internal/3333320116@sipserver.net) State HANGUP
2013-10-01 17:50:53.920072 [DEBUG] mod_sofia.c:504 Channel sofia/internal/3333320116@sipserver.net hanging up, cause: NORMAL_CLEARING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:48 sofia/internal/3333320116@sipserver.net Standard HANGUP, cause: NORMAL_CLEARING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:676 (sofia/internal/3333320116@sipserver.net) State HANGUP going to sleep
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:687 (sofia/internal/3333320116@sipserver.net) Callstate Change ACTIVE -> HANGUP
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/3333320116@sipserver.net) State Change CS_HANGUP -> CS_REPORTING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116@sipserver.net) Running State Change CS_REPORTING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:759 (sofia/internal/3333320116@sipserver.net) State REPORTING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:92 sofia/internal/3333320116@sipserver.net Standard REPORTING, cause: NORMAL_CLEARING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:759 (sofia/internal/3333320116@sipserver.net) State REPORTING going to sleep
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/3333320116@sipserver.net) State Change CS_REPORTING -> CS_DESTROY
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116@sipserver.net [BREAK]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:1541 Session 301 (sofia/internal/3333320116@sipserver.net) Locked, Waiting on external entities
2013-10-01 17:50:53.920072 [NOTICE] switch_core_session.c:1559 Session 301 (sofia/internal/3333320116@sipserver.net) Ended
2013-10-01 17:50:53.920072 [NOTICE] switch_core_session.c:1563 Close Channel sofia/internal/3333320116@sipserver.net [CS_DESTROY]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/3333320116@sipserver.net) Callstate Change HANGUP -> DOWN
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:568 (sofia/internal/3333320116@sipserver.net) Running State Change CS_DESTROY
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/3333320116@sipserver.net) State DESTROY
2013-10-01 17:50:53.920072 [DEBUG] mod_sofia.c:397 sofia/internal/3333320116@sipserver.net SOFIA DESTROY
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:99 sofia/internal/3333320116@sipserver.net Standard DESTROY
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/3333320116@sipserver.net) State DESTROY going to sleep