[Freeswitch-users] shared line music on hold problem

Thu Nov 14 17:58:00 MSK 2013

Hi all,

recently I have installed the latest version of Freeswitch (1.2.14) and 
I have found the following Issue.
If I call an extension connected to only a phone and transfer the call I 
can hear the music on hold.
Instead when I call a Shared line (extension shared between two phones) 
and I try to transfer the call I can't hear the music on hold.

I think is something related to the configuration of the shared line 
because with a normal line works good. Does someone have an Idea about 
what is going wrong?

I attach both logs of when I try to call a shared line and when i try to 
call a normal line.

Best Regards

Simone
-------------- next part --------------
2013-11-14 14:40:45.121959 [NOTICE] switch_channel.c:1034 New Channel sofia/internal/1401 at 192.168.4.1 [be883e4a-4d3a-11e3-a6be-2fceac34917d]
2013-11-14 14:40:45.121959 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:45.121959 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:45.121959 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1401 at 192.168.4.1) Running State Change CS_NEW
2013-11-14 14:40:45.121959 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/1401 at 192.168.4.1) State NEW
2013-11-14 14:40:45.141955 [DEBUG] sofia.c:7865 IP 192.168.4.28 Approved by acl "domains[]". Access Granted.
2013-11-14 14:40:45.141955 [DEBUG] sofia.c:5752 Channel sofia/internal/1401 at 192.168.4.1 entering state [received][100]
2013-11-14 14:40:45.141955 [DEBUG] sofia.c:5765 Remote SDP:
v=0
o=1401 5006 240 IN IP4 192.168.4.28
s=Mapping
c=IN IP4 192.168.4.28
t=0 0
m=audio 5006 RTP/AVP 8 0 18 96 97 2 9 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:96 G726-32/8000
a=rtpmap:97 AAL2-G726-32/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

2013-11-14 14:40:45.141955 [DEBUG] sofia.c:5979 (sofia/internal/1401 at 192.168.4.1) State Change CS_NEW -> CS_INIT
2013-11-14 14:40:45.141955 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1401 at 192.168.4.1) Running State Change CS_INIT
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/1401 at 192.168.4.1) State INIT
2013-11-14 14:40:45.141955 [DEBUG] mod_sofia.c:87 sofia/internal/1401 at 192.168.4.1 SOFIA INIT
2013-11-14 14:40:45.141955 [DEBUG] mod_sofia.c:127 (sofia/internal/1401 at 192.168.4.1) State Change CS_INIT -> CS_ROUTING
2013-11-14 14:40:45.141955 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/1401 at 192.168.4.1) State INIT going to sleep
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1401 at 192.168.4.1) Running State Change CS_ROUTING
2013-11-14 14:40:45.141955 [DEBUG] switch_channel.c:2115 (sofia/internal/1401 at 192.168.4.1) Callstate Change DOWN -> RINGING
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/1401 at 192.168.4.1) State ROUTING
2013-11-14 14:40:45.141955 [DEBUG] mod_sofia.c:150 sofia/internal/1401 at 192.168.4.1 SOFIA ROUTING
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:117 sofia/internal/1401 at 192.168.4.1 Standard ROUTING
2013-11-14 14:40:45.141955 [INFO] mod_dialplan_xml.c:558 Processing 1401 <1401>->1202 in context default
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1401 at 192.168.4.1 Date/Time Match (PASS) [tod_example] break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(open=true) 
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1401 at 192.168.4.1 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [global-intercept] destination_number(1202) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [group-intercept] destination_number(1202) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [intercept-ext] destination_number(1202) =~ /^\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->redial] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [redial] destination_number(1202) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->global] continue=true
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=1401 5006 240 IN IP4 192.168.4.28
s=Mapping
c=IN IP4 192.168.4.28
t=0 0
m=audio 5006 RTP/AVP 8 0 18 96 97 2 9 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:96 G726-32/8000
a=rtpmap:97 AAL2-G726-32/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1401 at 192.168.4.1 Absolute Condition [global]
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [snom-demo-2] destination_number(1202) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [snom-demo-1] destination_number(1202) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [eavesdrop] destination_number(1202) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [eavesdrop] destination_number(1202) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [call_return] destination_number(1202) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [del-group] destination_number(1202) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [add-group] destination_number(1202) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [call-group-simo] destination_number(1202) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [call-group-order] destination_number(1202) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [extension-intercom] destination_number(1202) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (PASS) [Local_Extension] destination_number(1202) =~ /^(1[0-9][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 Action export(dialed_extension=1202) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action bind_meta_app(1 b s execute_extension::dx XML features) 
Dialplan: sofia/internal/1401 at 192.168.4.1 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/1401 at 192.168.4.1 Action bind_meta_app(3 b s execute_extension::cf XML features) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(ringback=${us-ring}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(transfer_ringback=local_stream://moh) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(call_timeout=30) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(hangup_after_bridge=true) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(continue_on_fail=true) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action bridge(user/${dialed_extension}@${domain_name}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action answer() 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action sleep(1000) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/1401 at 192.168.4.1) State Change CS_ROUTING -> CS_EXECUTE
2013-11-14 14:40:45.141955 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/1401 at 192.168.4.1) State ROUTING going to sleep
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1401 at 192.168.4.1) Running State Change CS_EXECUTE
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/1401 at 192.168.4.1) State EXECUTE
2013-11-14 14:40:45.141955 [DEBUG] mod_sofia.c:243 sofia/internal/1401 at 192.168.4.1 SOFIA EXECUTE
2013-11-14 14:40:45.141955 [DEBUG] switch_core_state_machine.c:209 sofia/internal/1401 at 192.168.4.1 Standard EXECUTE
EXECUTE sofia/internal/1401 at 192.168.4.1 set(open=true)
2013-11-14 14:40:45.141955 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [open]=[true]
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-spymap/1401/be883e4a-4d3a-11e3-a6be-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial/1401/1202)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial/global/be883e4a-4d3a-11e3-a6be-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 export(RFC2822_DATE=Thu, 14 Nov 2013 14:40:45 +0000)
2013-11-14 14:40:45.141955 [DEBUG] switch_channel.c:1226 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 14 Nov 2013 14:40:45 +0000]
EXECUTE sofia/internal/1401 at 192.168.4.1 export(dialed_extension=1202)
2013-11-14 14:40:45.141955 [DEBUG] switch_channel.c:1226 EXPORT (export_vars) [dialed_extension]=[1202]
EXECUTE sofia/internal/1401 at 192.168.4.1 bind_meta_app(1 b s execute_extension::dx XML features)
2013-11-14 14:40:45.141955 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/1401 at 192.168.4.1 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1401.2013-11-14-14-40-45.wav)
2013-11-14 14:40:45.141955 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1401.2013-11-14-14-40-45.wav
EXECUTE sofia/internal/1401 at 192.168.4.1 bind_meta_app(3 b s execute_extension::cf XML features)
2013-11-14 14:40:45.141955 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/1401 at 192.168.4.1 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2013-11-14 14:40:45.141955 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/1401 at 192.168.4.1 set(ringback=%(2000,4000,440,480))
2013-11-14 14:40:45.141955 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/1401 at 192.168.4.1 set(transfer_ringback=local_stream://moh)
2013-11-14 14:40:45.141955 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1401 at 192.168.4.1 set(call_timeout=30)
2013-11-14 14:40:45.141955 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [call_timeout]=[30]
EXECUTE sofia/internal/1401 at 192.168.4.1 set(hangup_after_bridge=true)
2013-11-14 14:40:45.141955 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1401 at 192.168.4.1 set(continue_on_fail=true)
2013-11-14 14:40:45.141955 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-call_return/1202/1401)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial_ext/1202/be883e4a-4d3a-11e3-a6be-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 set(called_party_callgroup=)
2013-11-14 14:40:45.141955 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [called_party_callgroup]=[UNDEF]
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial_ext//be883e4a-4d3a-11e3-a6be-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial_ext/global/be883e4a-4d3a-11e3-a6be-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial//be883e4a-4d3a-11e3-a6be-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 bridge(user/1202 at 192.168.4.1)
2013-11-14 14:40:45.161954 [DEBUG] switch_channel.c:1180 sofia/internal/1401 at 192.168.4.1 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 14 Nov 2013 14:40:45 +0000] to event
2013-11-14 14:40:45.161954 [DEBUG] switch_channel.c:1180 sofia/internal/1401 at 192.168.4.1 EXPORTING[export_vars] [dialed_extension]=[1202] to event
2013-11-14 14:40:45.161954 [DEBUG] switch_ivr_originate.c:2060 Parsing global variables
2013-11-14 14:40:45.161954 [DEBUG] switch_channel.c:1180 sofia/internal/1401 at 192.168.4.1 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 14 Nov 2013 14:40:45 +0000] to event
2013-11-14 14:40:45.161954 [DEBUG] switch_channel.c:1180 sofia/internal/1401 at 192.168.4.1 EXPORTING[export_vars] [dialed_extension]=[1202] to event
2013-11-14 14:40:45.161954 [DEBUG] switch_ivr_originate.c:2060 Parsing global variables
2013-11-14 14:40:45.161954 [DEBUG] switch_event.c:1654 Parsing variable [sip_invite_domain]=[192.168.4.1]
2013-11-14 14:40:45.161954 [DEBUG] switch_event.c:1654 Parsing variable [presence_id]=[1202 at 192.168.4.1]
2013-11-14 14:40:45.161954 [NOTICE] switch_channel.c:1034 New Channel sofia/internal/sip:1202 at 192.168.4.31 [be8dbd70-4d3a-11e3-a6da-2fceac34917d]
2013-11-14 14:40:45.161954 [DEBUG] mod_sofia.c:5231 (sofia/internal/sip:1202 at 192.168.4.31) State Change CS_NEW -> CS_INIT
2013-11-14 14:40:45.161954 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:45.161954 [DEBUG] mod_sofia.c:5301 [zrtp_passthru] Setting a-leg inherit_codec=true
2013-11-14 14:40:45.161954 [DEBUG] mod_sofia.c:5304 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMA at 8000h@20i at 64000b,PCMU at 8000h@20i at 64000b,G722 at 8000h@20i at 64000b'
2013-11-14 14:40:45.161954 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1202 at 192.168.4.31) Running State Change CS_INIT
2013-11-14 14:40:45.161954 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/sip:1202 at 192.168.4.31) State INIT
2013-11-14 14:40:45.161954 [DEBUG] mod_sofia.c:87 sofia/internal/sip:1202 at 192.168.4.31 SOFIA INIT
2013-11-14 14:40:45.161954 [DEBUG] sofia_glue.c:2703 Local SDP:
v=0
o=FreeSWITCH 1384412193 1384412194 IN IP4 192.168.4.1
s=FreeSWITCH
c=IN IP4 192.168.4.1
t=0 0
m=audio 27852 RTP/AVP 8 0 9 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-11-14 14:40:45.161954 [DEBUG] mod_sofia.c:127 (sofia/internal/sip:1202 at 192.168.4.31) State Change CS_INIT -> CS_ROUTING
2013-11-14 14:40:45.161954 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:45.161954 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/sip:1202 at 192.168.4.31) State INIT going to sleep
2013-11-14 14:40:45.161954 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1202 at 192.168.4.31) Running State Change CS_ROUTING
2013-11-14 14:40:45.161954 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:45.161954 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/sip:1202 at 192.168.4.31) State ROUTING
2013-11-14 14:40:45.161954 [DEBUG] mod_sofia.c:150 sofia/internal/sip:1202 at 192.168.4.31 SOFIA ROUTING
2013-11-14 14:40:45.161954 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:1202 at 192.168.4.31) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-11-14 14:40:45.161954 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:45.161954 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/sip:1202 at 192.168.4.31) State ROUTING going to sleep
2013-11-14 14:40:45.161954 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1202 at 192.168.4.31) Running State Change CS_CONSUME_MEDIA
2013-11-14 14:40:45.161954 [DEBUG] switch_core_state_machine.c:489 (sofia/internal/sip:1202 at 192.168.4.31) State CONSUME_MEDIA
2013-11-14 14:40:45.161954 [DEBUG] switch_core_state_machine.c:489 (sofia/internal/sip:1202 at 192.168.4.31) State CONSUME_MEDIA going to sleep
2013-11-14 14:40:45.161954 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1202 at 192.168.4.31 entering state [calling][0]
2013-11-14 14:40:45.221965 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:45.221965 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:45.221965 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1202 at 192.168.4.31 entering state [proceeding][180]
2013-11-14 14:40:45.221965 [NOTICE] sofia.c:5847 Ring-Ready sofia/internal/sip:1202 at 192.168.4.31!
2013-11-14 14:40:45.221965 [DEBUG] switch_channel.c:3189 (sofia/internal/sip:1202 at 192.168.4.31) Callstate Change DOWN -> RINGING
2013-11-14 14:40:45.241956 [INFO] switch_ivr_originate.c:1190 Sending early media
2013-11-14 14:40:45.241956 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2013-11-14 14:40:45.241956 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-11-14 14:40:45.241956 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-11-14 14:40:45.241956 [DEBUG] sofia_glue.c:3150 Set Codec sofia/internal/1401 at 192.168.4.1 PCMA/8000 20 ms 160 samples 64000 bits
2013-11-14 14:40:45.241956 [DEBUG] switch_core_codec.c:111 sofia/internal/1401 at 192.168.4.1 Original read codec set to PCMA:8
2013-11-14 14:40:45.241956 [DEBUG] sofia_glue.c:5356 Set 2833 dtmf send/recv payload to 101
2013-11-14 14:40:45.241956 [DEBUG] sofia_glue.c:3409 AUDIO RTP [sofia/internal/1401 at 192.168.4.1] 192.168.4.1 port 31854 -> 192.168.4.28 port 5006 codec: 8 ms: 20
2013-11-14 14:40:45.241956 [DEBUG] switch_rtp.c:1975 Starting timer [soft] 160 bytes per 20ms
2013-11-14 14:40:45.241956 [DEBUG] sofia_glue.c:3676 Set 2833 dtmf send payload to 101
2013-11-14 14:40:45.241956 [DEBUG] sofia_glue.c:3682 Set 2833 dtmf receive payload to 101
2013-11-14 14:40:45.241956 [DEBUG] sofia_glue.c:3709 sofia/internal/1401 at 192.168.4.1 Set rtp dtmf delay to 40
2013-11-14 14:40:45.241956 [NOTICE] sofia_glue.c:4320 Pre-Answer sofia/internal/1401 at 192.168.4.1!
2013-11-14 14:40:45.241956 [DEBUG] switch_channel.c:3315 (sofia/internal/1401 at 192.168.4.1) Callstate Change RINGING -> EARLY
2013-11-14 14:40:45.241956 [DEBUG] mod_sofia.c:2885 Ring SDP:
v=0
o=FreeSWITCH 1384408191 1384408192 IN IP4 192.168.4.1
s=FreeSWITCH
c=IN IP4 192.168.4.1
t=0 0
m=audio 31854 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-11-14 14:40:45.241956 [DEBUG] switch_core_session.c:858 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:45.241956 [DEBUG] switch_ivr_originate.c:1247 Raw Codec Activation Success L16 at 8000hz 1 channel 20ms
2013-11-14 14:40:45.241956 [DEBUG] switch_core_codec.c:219 sofia/internal/1401 at 192.168.4.1 Push codec L16:70
2013-11-14 14:40:45.241956 [DEBUG] switch_ivr_originate.c:1315 Play Ringback Tone [%(2000,4000,440,480)]
2013-11-14 14:40:45.241956 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:45.261953 [DEBUG] sofia.c:5752 Channel sofia/internal/1401 at 192.168.4.1 entering state [early][183]
2013-11-14 14:40:45.341947 [DEBUG] switch_rtp.c:3690 Correct ip/port confirmed.
2013-11-14 14:40:46.321948 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.321948 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.321948 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1202 at 192.168.4.31 entering state [completing][200]
2013-11-14 14:40:46.321948 [DEBUG] sofia.c:5765 Remote SDP:
v=0
o=- 1384440045 1384440045 IN IP4 192.168.4.31
s=Polycom IP Phone
c=IN IP4 192.168.4.31
t=0 0
m=audio 2242 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000

2013-11-14 14:40:46.321948 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.321948 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.321948 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1202 at 192.168.4.31 entering state [ready][200]
2013-11-14 14:40:46.321948 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-11-14 14:40:46.321948 [DEBUG] sofia_glue.c:3150 Set Codec sofia/internal/sip:1202 at 192.168.4.31 PCMA/8000 20 ms 160 samples 64000 bits
2013-11-14 14:40:46.321948 [DEBUG] switch_core_codec.c:111 sofia/internal/sip:1202 at 192.168.4.31 Original read codec set to PCMA:8
2013-11-14 14:40:46.321948 [DEBUG] sofia_glue.c:5347 Set 2833 dtmf send payload to 101
2013-11-14 14:40:46.321948 [DEBUG] sofia_glue.c:3409 AUDIO RTP [sofia/internal/sip:1202 at 192.168.4.31] 192.168.4.1 port 27852 -> 192.168.4.31 port 2242 codec: 8 ms: 20
2013-11-14 14:40:46.321948 [DEBUG] switch_rtp.c:1975 Starting timer [soft] 160 bytes per 20ms
2013-11-14 14:40:46.321948 [DEBUG] sofia_glue.c:3676 Set 2833 dtmf send payload to 101
2013-11-14 14:40:46.321948 [DEBUG] sofia_glue.c:3682 Set 2833 dtmf receive payload to 101
2013-11-14 14:40:46.321948 [DEBUG] sofia_glue.c:3709 sofia/internal/sip:1202 at 192.168.4.31 Set rtp dtmf delay to 40
2013-11-14 14:40:46.321948 [DEBUG] switch_channel.c:3548 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:46.321948 [NOTICE] sofia.c:6508 Channel [sofia/internal/sip:1202 at 192.168.4.31] has been answered
2013-11-14 14:40:46.321948 [DEBUG] switch_channel.c:3594 (sofia/internal/sip:1202 at 192.168.4.31) Callstate Change RINGING -> ACTIVE
2013-11-14 14:40:46.341953 [DEBUG] switch_core_codec.c:244 sofia/internal/1401 at 192.168.4.1 Restore previous codec PCMA:8.
2013-11-14 14:40:46.441949 [DEBUG] mod_sofia.c:866 Local SDP sofia/internal/1401 at 192.168.4.1:
v=0
o=FreeSWITCH 1384408191 1384408193 IN IP4 192.168.4.1
s=FreeSWITCH
c=IN IP4 192.168.4.1
t=0 0
m=audio 31854 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-11-14 14:40:46.441949 [DEBUG] switch_core_session.c:858 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:46.441949 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:46.441949 [NOTICE] switch_ivr_originate.c:3437 Channel [sofia/internal/1401 at 192.168.4.1] has been answered
2013-11-14 14:40:46.441949 [DEBUG] switch_channel.c:3594 (sofia/internal/1401 at 192.168.4.1) Callstate Change EARLY -> ACTIVE
2013-11-14 14:40:46.441949 [DEBUG] sofia.c:5752 Channel sofia/internal/1401 at 192.168.4.1 entering state [completed][200]
2013-11-14 14:40:46.441949 [DEBUG] switch_ivr_originate.c:3494 Originate Resulted in Success: [sofia/internal/sip:1202 at 192.168.4.31]
2013-11-14 14:40:46.441949 [DEBUG] switch_ivr_originate.c:3494 Originate Resulted in Success: [sofia/internal/sip:1202 at 192.168.4.31]
2013-11-14 14:40:46.441949 [DEBUG] switch_core_session.c:858 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.441949 [DEBUG] switch_core_session.c:858 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:46.441949 [DEBUG] switch_ivr_bridge.c:1426 (sofia/internal/sip:1202 at 192.168.4.31) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2013-11-14 14:40:46.441949 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.441949 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1202 at 192.168.4.31) Running State Change CS_EXCHANGE_MEDIA
2013-11-14 14:40:46.441949 [DEBUG] switch_core_state_machine.c:480 (sofia/internal/sip:1202 at 192.168.4.31) State EXCHANGE_MEDIA
2013-11-14 14:40:46.441949 [DEBUG] mod_sofia.c:688 SOFIA EXCHANGE_MEDIA
2013-11-14 14:40:46.481951 [DEBUG] switch_rtp.c:3690 Correct ip/port confirmed.
2013-11-14 14:40:46.661949 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:46.661949 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:46.661949 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:46.681951 [DEBUG] sofia.c:5752 Channel sofia/internal/1401 at 192.168.4.1 entering state [ready][200]
2013-11-14 14:40:46.681951 [DEBUG] switch_core_session.c:920 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.681951 [DEBUG] switch_core_session.c:920 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:46.701956 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.701956 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1202 at 192.168.4.31 entering state [calling][0]
2013-11-14 14:40:46.701956 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.701956 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.701956 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:46.721952 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1202 at 192.168.4.31 entering state [ready][200]
2013-11-14 14:40:46.721952 [DEBUG] sofia.c:5762 Duplicate SDP
v=0
o=- 1384440045 1384440045 IN IP4 192.168.4.31
s=Polycom IP Phone
c=IN IP4 192.168.4.31
t=0 0
m=audio 2242 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000

2013-11-14 14:40:46.721952 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-11-14 14:40:46.721952 [DEBUG] sofia_glue.c:3079 Already using PCMA
2013-11-14 14:40:46.721952 [DEBUG] sofia_glue.c:5347 Set 2833 dtmf send payload to 101
2013-11-14 14:40:46.721952 [DEBUG] sofia.c:6350 Processing updated SDP
2013-11-14 14:40:46.721952 [DEBUG] sofia_glue.c:3379 Audio params are unchanged for sofia/internal/sip:1202 at 192.168.4.31.
2013-11-14 14:40:46.721952 [DEBUG] sofia_glue.c:3389 sofia/internal/sip:1202 at 192.168.4.31 Setting audio receive payload in Re-INVITE to 8
2013-11-14 14:40:48.221951 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:48.221951 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:48.241951 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1202 at 192.168.4.31 entering state [received][100]
2013-11-14 14:40:48.241951 [DEBUG] sofia.c:5765 Remote SDP:
v=0
o=- 1384440045 1384440046 IN IP4 192.168.4.31
s=Polycom IP Phone
c=IN IP4 0.0.0.0
t=0 0
m=audio 2242 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=sendonly

2013-11-14 14:40:48.241951 [DEBUG] switch_channel.c:1750 (sofia/internal/sip:1202 at 192.168.4.31) Callstate Change ACTIVE -> HELD
2013-11-14 14:40:48.241951 [DEBUG] switch_core_session.c:1138 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:48.261960 [DEBUG] switch_core_session.c:858 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:40:48.381953 [DEBUG] switch_ivr.c:615 sofia/internal/1401 at 192.168.4.1 Command Execute playback(local_stream://moh)
EXECUTE sofia/internal/1401 at 192.168.4.1 playback(local_stream://moh)
2013-11-14 14:40:48.381953 [DEBUG] mod_local_stream.c:497 Opening Stream [moh/8000] 8000hz
2013-11-14 14:40:48.381953 [DEBUG] switch_ivr_play_say.c:1319 Codec Activated L16 at 8000hz 1 channels 20ms
2013-11-14 14:40:48.481953 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-11-14 14:40:48.481953 [DEBUG] sofia_glue.c:3079 Already using PCMA
2013-11-14 14:40:48.481953 [DEBUG] sofia_glue.c:5347 Set 2833 dtmf send payload to 101
2013-11-14 14:40:48.481953 [DEBUG] sofia_glue.c:3398 Audio params changed for sofia/internal/sip:1202 at 192.168.4.31 from 192.168.4.31:2242 to 0.0.0.0:2242
2013-11-14 14:40:48.481953 [DEBUG] sofia_glue.c:3409 AUDIO RTP [sofia/internal/sip:1202 at 192.168.4.31] 192.168.4.1 port 27852 -> 0.0.0.0 port 2242 codec: 8 ms: 20
2013-11-14 14:40:48.481953 [DEBUG] sofia_glue.c:3448 AUDIO RTP CHANGING DEST TO: [0.0.0.0:2242]
2013-11-14 14:40:48.481953 [DEBUG] sofia.c:6298 Processing updated SDP
2013-11-14 14:40:48.481953 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:48.501958 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:48.501958 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:48.501958 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1202 at 192.168.4.31 [BREAK]
2013-11-14 14:40:48.521959 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1202 at 192.168.4.31 entering state [completed][200]
2013-11-14 14:40:48.521959 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1202 at 192.168.4.31 entering state [ready][200]
-------------- next part --------------
2013-11-14 14:43:54.901954 [NOTICE] switch_channel.c:1034 New Channel sofia/internal/1401 at 192.168.4.1 [2fa7c898-4d3b-11e3-a70a-2fceac34917d]
2013-11-14 14:43:54.901954 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:54.901954 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:54.901954 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1401 at 192.168.4.1) Running State Change CS_NEW
2013-11-14 14:43:54.901954 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/1401 at 192.168.4.1) State NEW
2013-11-14 14:43:54.921966 [DEBUG] sofia.c:7865 IP 192.168.4.28 Approved by acl "domains[]". Access Granted.
2013-11-14 14:43:54.921966 [WARNING] sofia.c:8472 Auto-Fixing Broken SLA [<sip:192.168.4.1>;appearance-index=1]
2013-11-14 14:43:54.921966 [DEBUG] sofia.c:5752 Channel sofia/internal/1401 at 192.168.4.1 entering state [received][100]
2013-11-14 14:43:54.921966 [DEBUG] sofia.c:5765 Remote SDP:
v=0
o=1401 5008 241 IN IP4 192.168.4.28
s=Mapping
c=IN IP4 192.168.4.28
t=0 0
m=audio 5008 RTP/AVP 8 0 18 96 97 2 9 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:96 G726-32/8000
a=rtpmap:97 AAL2-G726-32/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

2013-11-14 14:43:54.921966 [DEBUG] sofia.c:5979 (sofia/internal/1401 at 192.168.4.1) State Change CS_NEW -> CS_INIT
2013-11-14 14:43:54.921966 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:54.921966 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1401 at 192.168.4.1) Running State Change CS_INIT
2013-11-14 14:43:54.921966 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/1401 at 192.168.4.1) State INIT
2013-11-14 14:43:54.921966 [DEBUG] mod_sofia.c:87 sofia/internal/1401 at 192.168.4.1 SOFIA INIT
2013-11-14 14:43:54.921966 [DEBUG] mod_sofia.c:127 (sofia/internal/1401 at 192.168.4.1) State Change CS_INIT -> CS_ROUTING
2013-11-14 14:43:54.921966 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:54.921966 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/1401 at 192.168.4.1) State INIT going to sleep
2013-11-14 14:43:54.921966 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1401 at 192.168.4.1) Running State Change CS_ROUTING
2013-11-14 14:43:54.921966 [DEBUG] switch_channel.c:2115 (sofia/internal/1401 at 192.168.4.1) Callstate Change DOWN -> RINGING
2013-11-14 14:43:54.921966 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/1401 at 192.168.4.1) State ROUTING
2013-11-14 14:43:54.921966 [DEBUG] mod_sofia.c:150 sofia/internal/1401 at 192.168.4.1 SOFIA ROUTING
2013-11-14 14:43:54.921966 [DEBUG] switch_core_state_machine.c:117 sofia/internal/1401 at 192.168.4.1 Standard ROUTING
2013-11-14 14:43:54.921966 [INFO] mod_dialplan_xml.c:558 Processing 1401 <1401>->1200 in context default
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1401 at 192.168.4.1 Date/Time Match (PASS) [tod_example] break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(open=true) 
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1401 at 192.168.4.1 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [global-intercept] destination_number(1200) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [group-intercept] destination_number(1200) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [intercept-ext] destination_number(1200) =~ /^\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->redial] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [redial] destination_number(1200) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->global] continue=true
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=1401 5008 241 IN IP4 192.168.4.28
s=Mapping
c=IN IP4 192.168.4.28
t=0 0
m=audio 5008 RTP/AVP 8 0 18 96 97 2 9 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:96 G726-32/8000
a=rtpmap:97 AAL2-G726-32/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1401 at 192.168.4.1 Absolute Condition [global]
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [snom-demo-2] destination_number(1200) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [snom-demo-1] destination_number(1200) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [eavesdrop] destination_number(1200) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [eavesdrop] destination_number(1200) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [call_return] destination_number(1200) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [del-group] destination_number(1200) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [add-group] destination_number(1200) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [call-group-simo] destination_number(1200) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [call-group-order] destination_number(1200) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (FAIL) [extension-intercom] destination_number(1200) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1401 at 192.168.4.1 Regex (PASS) [Local_Extension] destination_number(1200) =~ /^(1[0-9][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/1401 at 192.168.4.1 Action export(dialed_extension=1200) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action bind_meta_app(1 b s execute_extension::dx XML features) 
Dialplan: sofia/internal/1401 at 192.168.4.1 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/1401 at 192.168.4.1 Action bind_meta_app(3 b s execute_extension::cf XML features) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(ringback=${us-ring}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(transfer_ringback=local_stream://moh) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(call_timeout=30) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(hangup_after_bridge=true) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(continue_on_fail=true) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action bridge(user/${dialed_extension}@${domain_name}) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action answer() 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action sleep(1000) 
Dialplan: sofia/internal/1401 at 192.168.4.1 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/1401 at 192.168.4.1) State Change CS_ROUTING -> CS_EXECUTE
2013-11-14 14:43:54.941953 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/1401 at 192.168.4.1) State ROUTING going to sleep
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1401 at 192.168.4.1) Running State Change CS_EXECUTE
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/1401 at 192.168.4.1) State EXECUTE
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:243 sofia/internal/1401 at 192.168.4.1 SOFIA EXECUTE
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:209 sofia/internal/1401 at 192.168.4.1 Standard EXECUTE
EXECUTE sofia/internal/1401 at 192.168.4.1 set(open=true)
2013-11-14 14:43:54.941953 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [open]=[true]
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-spymap/1401/2fa7c898-4d3b-11e3-a70a-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial/1401/1200)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial/global/2fa7c898-4d3b-11e3-a70a-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 export(RFC2822_DATE=Thu, 14 Nov 2013 14:43:54 +0000)
2013-11-14 14:43:54.941953 [DEBUG] switch_channel.c:1226 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 14 Nov 2013 14:43:54 +0000]
EXECUTE sofia/internal/1401 at 192.168.4.1 export(dialed_extension=1200)
2013-11-14 14:43:54.941953 [DEBUG] switch_channel.c:1226 EXPORT (export_vars) [dialed_extension]=[1200]
EXECUTE sofia/internal/1401 at 192.168.4.1 bind_meta_app(1 b s execute_extension::dx XML features)
2013-11-14 14:43:54.941953 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/1401 at 192.168.4.1 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1401.2013-11-14-14-43-54.wav)
2013-11-14 14:43:54.941953 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1401.2013-11-14-14-43-54.wav
EXECUTE sofia/internal/1401 at 192.168.4.1 bind_meta_app(3 b s execute_extension::cf XML features)
2013-11-14 14:43:54.941953 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/1401 at 192.168.4.1 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2013-11-14 14:43:54.941953 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/1401 at 192.168.4.1 set(ringback=%(2000,4000,440,480))
2013-11-14 14:43:54.941953 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/1401 at 192.168.4.1 set(transfer_ringback=local_stream://moh)
2013-11-14 14:43:54.941953 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1401 at 192.168.4.1 set(call_timeout=30)
2013-11-14 14:43:54.941953 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [call_timeout]=[30]
EXECUTE sofia/internal/1401 at 192.168.4.1 set(hangup_after_bridge=true)
2013-11-14 14:43:54.941953 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1401 at 192.168.4.1 set(continue_on_fail=true)
2013-11-14 14:43:54.941953 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-call_return/1200/1401)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial_ext/1200/2fa7c898-4d3b-11e3-a70a-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 set(called_party_callgroup=)
2013-11-14 14:43:54.941953 [DEBUG] mod_dptools.c:1402 sofia/internal/1401 at 192.168.4.1 SET [called_party_callgroup]=[UNDEF]
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial_ext//2fa7c898-4d3b-11e3-a70a-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial_ext/global/2fa7c898-4d3b-11e3-a70a-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 hash(insert/192.168.4.1-last_dial//2fa7c898-4d3b-11e3-a70a-2fceac34917d)
EXECUTE sofia/internal/1401 at 192.168.4.1 bridge(user/1200 at 192.168.4.1)
2013-11-14 14:43:54.941953 [DEBUG] switch_channel.c:1180 sofia/internal/1401 at 192.168.4.1 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 14 Nov 2013 14:43:54 +0000] to event
2013-11-14 14:43:54.941953 [DEBUG] switch_channel.c:1180 sofia/internal/1401 at 192.168.4.1 EXPORTING[export_vars] [dialed_extension]=[1200] to event
2013-11-14 14:43:54.941953 [DEBUG] switch_ivr_originate.c:2060 Parsing global variables
2013-11-14 14:43:54.941953 [DEBUG] switch_channel.c:1180 sofia/internal/1401 at 192.168.4.1 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 14 Nov 2013 14:43:54 +0000] to event
2013-11-14 14:43:54.941953 [DEBUG] switch_channel.c:1180 sofia/internal/1401 at 192.168.4.1 EXPORTING[export_vars] [dialed_extension]=[1200] to event
2013-11-14 14:43:54.941953 [DEBUG] switch_ivr_originate.c:2060 Parsing global variables
2013-11-14 14:43:54.941953 [DEBUG] switch_event.c:1654 Parsing variable [sip_invite_domain]=[192.168.4.1]
2013-11-14 14:43:54.941953 [DEBUG] switch_event.c:1654 Parsing variable [presence_id]=[1200 at 192.168.4.1]
2013-11-14 14:43:54.941953 [NOTICE] switch_channel.c:1034 New Channel sofia/internal/sip:1200 at 192.168.4.30 [2fad9fd4-4d3b-11e3-a726-2fceac34917d]
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:5231 (sofia/internal/sip:1200 at 192.168.4.30) State Change CS_NEW -> CS_INIT
2013-11-14 14:43:54.941953 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.30 [BREAK]
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:5301 [zrtp_passthru] Setting a-leg inherit_codec=true
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:5304 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMA at 8000h@20i at 64000b,PCMU at 8000h@20i at 64000b,G722 at 8000h@20i at 64000b'
2013-11-14 14:43:54.941953 [NOTICE] switch_channel.c:1034 New Channel sofia/internal/sip:1200 at 192.168.4.31 [2fadc752-4d3b-11e3-a72b-2fceac34917d]
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:5231 (sofia/internal/sip:1200 at 192.168.4.31) State Change CS_NEW -> CS_INIT
2013-11-14 14:43:54.941953 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1200 at 192.168.4.30) Running State Change CS_INIT
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:5301 [zrtp_passthru] Setting a-leg inherit_codec=true
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:5304 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMA at 8000h@20i at 64000b,PCMU at 8000h@20i at 64000b,G722 at 8000h@20i at 64000b'
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/sip:1200 at 192.168.4.30) State INIT
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:87 sofia/internal/sip:1200 at 192.168.4.30 SOFIA INIT
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1200 at 192.168.4.31) Running State Change CS_INIT
2013-11-14 14:43:54.941953 [DEBUG] sofia_glue.c:2703 Local SDP:
v=0
o=FreeSWITCH 1384410250 1384410251 IN IP4 192.168.4.1
s=FreeSWITCH
c=IN IP4 192.168.4.1
t=0 0
m=audio 29984 RTP/AVP 8 0 9 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:127 (sofia/internal/sip:1200 at 192.168.4.30) State Change CS_INIT -> CS_ROUTING
2013-11-14 14:43:54.941953 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.30 [BREAK]
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/sip:1200 at 192.168.4.30) State INIT going to sleep
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1200 at 192.168.4.30) Running State Change CS_ROUTING
2013-11-14 14:43:54.941953 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.30 [BREAK]
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/sip:1200 at 192.168.4.31) State INIT
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:87 sofia/internal/sip:1200 at 192.168.4.31 SOFIA INIT
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/sip:1200 at 192.168.4.30) State ROUTING
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:150 sofia/internal/sip:1200 at 192.168.4.30 SOFIA ROUTING
2013-11-14 14:43:54.941953 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:1200 at 192.168.4.30) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-11-14 14:43:54.941953 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.30 [BREAK]
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/sip:1200 at 192.168.4.30) State ROUTING going to sleep
2013-11-14 14:43:54.941953 [DEBUG] sofia_glue.c:2703 Local SDP:
v=0
o=FreeSWITCH 1384414924 1384414925 IN IP4 192.168.4.1
s=FreeSWITCH
c=IN IP4 192.168.4.1
t=0 0
m=audio 25310 RTP/AVP 8 0 9 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-11-14 14:43:54.941953 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:54.941953 [DEBUG] mod_sofia.c:127 (sofia/internal/sip:1200 at 192.168.4.31) State Change CS_INIT -> CS_ROUTING
2013-11-14 14:43:54.941953 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/sip:1200 at 192.168.4.31) State INIT going to sleep
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1200 at 192.168.4.30) Running State Change CS_CONSUME_MEDIA
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:489 (sofia/internal/sip:1200 at 192.168.4.30) State CONSUME_MEDIA
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:489 (sofia/internal/sip:1200 at 192.168.4.30) State CONSUME_MEDIA going to sleep
2013-11-14 14:43:54.941953 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1200 at 192.168.4.30 entering state [calling][0]
2013-11-14 14:43:54.941953 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1200 at 192.168.4.31) Running State Change CS_ROUTING
2013-11-14 14:43:54.961953 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/sip:1200 at 192.168.4.31) State ROUTING
2013-11-14 14:43:54.961953 [DEBUG] mod_sofia.c:150 sofia/internal/sip:1200 at 192.168.4.31 SOFIA ROUTING
2013-11-14 14:43:54.961953 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:1200 at 192.168.4.31) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-11-14 14:43:54.961953 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:54.961953 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/sip:1200 at 192.168.4.31) State ROUTING going to sleep
2013-11-14 14:43:54.961953 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1200 at 192.168.4.31) Running State Change CS_CONSUME_MEDIA
2013-11-14 14:43:54.961953 [DEBUG] switch_core_state_machine.c:489 (sofia/internal/sip:1200 at 192.168.4.31) State CONSUME_MEDIA
2013-11-14 14:43:54.961953 [DEBUG] switch_core_state_machine.c:489 (sofia/internal/sip:1200 at 192.168.4.31) State CONSUME_MEDIA going to sleep
2013-11-14 14:43:54.961953 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1200 at 192.168.4.31 entering state [calling][0]
2013-11-14 14:43:55.001959 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.30 [BREAK]
2013-11-14 14:43:55.001959 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.30 [BREAK]
2013-11-14 14:43:55.001959 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.001959 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.021951 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1200 at 192.168.4.31 entering state [proceeding][180]
2013-11-14 14:43:55.021951 [NOTICE] sofia.c:5847 Ring-Ready sofia/internal/sip:1200 at 192.168.4.31!
2013-11-14 14:43:55.021951 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1200 at 192.168.4.30 entering state [proceeding][180]
2013-11-14 14:43:55.021951 [NOTICE] sofia.c:5847 Ring-Ready sofia/internal/sip:1200 at 192.168.4.30!
2013-11-14 14:43:55.021951 [DEBUG] switch_channel.c:3189 (sofia/internal/sip:1200 at 192.168.4.31) Callstate Change DOWN -> RINGING
2013-11-14 14:43:55.021951 [DEBUG] switch_channel.c:3189 (sofia/internal/sip:1200 at 192.168.4.30) Callstate Change DOWN -> RINGING
2013-11-14 14:43:55.041956 [INFO] switch_ivr_originate.c:1190 Sending early media
2013-11-14 14:43:55.041956 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2013-11-14 14:43:55.041956 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-11-14 14:43:55.041956 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-11-14 14:43:55.041956 [DEBUG] sofia_glue.c:3150 Set Codec sofia/internal/1401 at 192.168.4.1 PCMA/8000 20 ms 160 samples 64000 bits
2013-11-14 14:43:55.041956 [DEBUG] switch_core_codec.c:111 sofia/internal/1401 at 192.168.4.1 Original read codec set to PCMA:8
2013-11-14 14:43:55.041956 [DEBUG] sofia_glue.c:5356 Set 2833 dtmf send/recv payload to 101
2013-11-14 14:43:55.041956 [DEBUG] sofia_glue.c:3409 AUDIO RTP [sofia/internal/1401 at 192.168.4.1] 192.168.4.1 port 23304 -> 192.168.4.28 port 5008 codec: 8 ms: 20
2013-11-14 14:43:55.041956 [DEBUG] switch_rtp.c:1975 Starting timer [soft] 160 bytes per 20ms
2013-11-14 14:43:55.041956 [DEBUG] sofia_glue.c:3676 Set 2833 dtmf send payload to 101
2013-11-14 14:43:55.041956 [DEBUG] sofia_glue.c:3682 Set 2833 dtmf receive payload to 101
2013-11-14 14:43:55.041956 [DEBUG] sofia_glue.c:3709 sofia/internal/1401 at 192.168.4.1 Set rtp dtmf delay to 40
2013-11-14 14:43:55.041956 [NOTICE] sofia_glue.c:4320 Pre-Answer sofia/internal/1401 at 192.168.4.1!
2013-11-14 14:43:55.041956 [DEBUG] switch_channel.c:3315 (sofia/internal/1401 at 192.168.4.1) Callstate Change RINGING -> EARLY
2013-11-14 14:43:55.041956 [DEBUG] mod_sofia.c:2885 Ring SDP:
v=0
o=FreeSWITCH 1384416931 1384416932 IN IP4 192.168.4.1
s=FreeSWITCH
c=IN IP4 192.168.4.1
t=0 0
m=audio 23304 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-11-14 14:43:55.041956 [DEBUG] switch_core_session.c:858 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.041956 [DEBUG] switch_ivr_originate.c:1247 Raw Codec Activation Success L16 at 8000hz 1 channel 20ms
2013-11-14 14:43:55.041956 [DEBUG] switch_core_codec.c:219 sofia/internal/1401 at 192.168.4.1 Push codec L16:70
2013-11-14 14:43:55.041956 [DEBUG] switch_ivr_originate.c:1315 Play Ringback Tone [%(2000,4000,440,480)]
2013-11-14 14:43:55.041956 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.061967 [DEBUG] sofia.c:5752 Channel sofia/internal/1401 at 192.168.4.1 entering state [early][183]
2013-11-14 14:43:55.121963 [DEBUG] switch_rtp.c:3690 Correct ip/port confirmed.
2013-11-14 14:43:55.661953 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.661953 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.661953 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1200 at 192.168.4.31 entering state [completing][200]
2013-11-14 14:43:55.661953 [DEBUG] sofia.c:5765 Remote SDP:
v=0
o=- 1384440235 1384440235 IN IP4 192.168.4.31
s=Polycom IP Phone
c=IN IP4 192.168.4.31
t=0 0
m=audio 2244 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000

2013-11-14 14:43:55.661953 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.661953 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.661953 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1200 at 192.168.4.31 entering state [ready][200]
2013-11-14 14:43:55.661953 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-11-14 14:43:55.661953 [DEBUG] sofia_glue.c:3150 Set Codec sofia/internal/sip:1200 at 192.168.4.31 PCMA/8000 20 ms 160 samples 64000 bits
2013-11-14 14:43:55.661953 [DEBUG] switch_core_codec.c:111 sofia/internal/sip:1200 at 192.168.4.31 Original read codec set to PCMA:8
2013-11-14 14:43:55.661953 [DEBUG] sofia_glue.c:5347 Set 2833 dtmf send payload to 101
2013-11-14 14:43:55.661953 [DEBUG] sofia_glue.c:3409 AUDIO RTP [sofia/internal/sip:1200 at 192.168.4.31] 192.168.4.1 port 25310 -> 192.168.4.31 port 2244 codec: 8 ms: 20
2013-11-14 14:43:55.661953 [DEBUG] switch_rtp.c:1975 Starting timer [soft] 160 bytes per 20ms
2013-11-14 14:43:55.661953 [DEBUG] sofia_glue.c:3676 Set 2833 dtmf send payload to 101
2013-11-14 14:43:55.661953 [DEBUG] sofia_glue.c:3682 Set 2833 dtmf receive payload to 101
2013-11-14 14:43:55.661953 [DEBUG] sofia_glue.c:3709 sofia/internal/sip:1200 at 192.168.4.31 Set rtp dtmf delay to 40
2013-11-14 14:43:55.661953 [DEBUG] switch_channel.c:3548 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.661953 [NOTICE] sofia.c:6508 Channel [sofia/internal/sip:1200 at 192.168.4.31] has been answered
2013-11-14 14:43:55.661953 [DEBUG] switch_channel.c:3594 (sofia/internal/sip:1200 at 192.168.4.31) Callstate Change RINGING -> ACTIVE
2013-11-14 14:43:55.681950 [DEBUG] switch_core_codec.c:244 sofia/internal/1401 at 192.168.4.1 Restore previous codec PCMA:8.
2013-11-14 14:43:55.681950 [NOTICE] switch_ivr_originate.c:3410 Hangup sofia/internal/sip:1200 at 192.168.4.30 [CS_CONSUME_MEDIA] [LOSE_RACE]
2013-11-14 14:43:55.681950 [DEBUG] switch_channel.c:3134 Send signal sofia/internal/sip:1200 at 192.168.4.30 [KILL]
2013-11-14 14:43:55.681950 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.30 [BREAK]
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1200 at 192.168.4.30) Running State Change CS_HANGUP
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:678 (sofia/internal/sip:1200 at 192.168.4.30) State HANGUP
2013-11-14 14:43:55.681950 [DEBUG] mod_sofia.c:506 Channel sofia/internal/sip:1200 at 192.168.4.30 hanging up, cause: LOSE_RACE
2013-11-14 14:43:55.681950 [DEBUG] mod_sofia.c:866 Local SDP sofia/internal/1401 at 192.168.4.1:
v=0
o=FreeSWITCH 1384416931 1384416933 IN IP4 192.168.4.1
s=FreeSWITCH
c=IN IP4 192.168.4.1
t=0 0
m=audio 23304 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-11-14 14:43:55.681950 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.681950 [DEBUG] sofia.c:5752 Channel sofia/internal/1401 at 192.168.4.1 entering state [completed][200]
2013-11-14 14:43:55.681950 [DEBUG] switch_core_session.c:858 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.681950 [DEBUG] mod_sofia.c:568 Sending CANCEL to sofia/internal/sip:1200 at 192.168.4.30
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:1200 at 192.168.4.30 Standard HANGUP, cause: LOSE_RACE
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:678 (sofia/internal/sip:1200 at 192.168.4.30) State HANGUP going to sleep
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:689 (sofia/internal/sip:1200 at 192.168.4.30) Callstate Change RINGING -> HANGUP
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/sip:1200 at 192.168.4.30) State Change CS_HANGUP -> CS_REPORTING
2013-11-14 14:43:55.681950 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.30 [BREAK]
2013-11-14 14:43:55.681950 [NOTICE] switch_ivr_originate.c:3437 Channel [sofia/internal/1401 at 192.168.4.1] has been answered
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1200 at 192.168.4.30) Running State Change CS_REPORTING
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:761 (sofia/internal/sip:1200 at 192.168.4.30) State REPORTING
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:92 sofia/internal/sip:1200 at 192.168.4.30 Standard REPORTING, cause: LOSE_RACE
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:761 (sofia/internal/sip:1200 at 192.168.4.30) State REPORTING going to sleep
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/sip:1200 at 192.168.4.30) State Change CS_REPORTING -> CS_DESTROY
2013-11-14 14:43:55.681950 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.30 [BREAK]
2013-11-14 14:43:55.681950 [DEBUG] switch_core_session.c:1546 Session 1471 (sofia/internal/sip:1200 at 192.168.4.30) Locked, Waiting on external entities
2013-11-14 14:43:55.681950 [DEBUG] switch_channel.c:3594 (sofia/internal/1401 at 192.168.4.1) Callstate Change EARLY -> ACTIVE
2013-11-14 14:43:55.681950 [DEBUG] switch_ivr_originate.c:3494 Originate Resulted in Success: [sofia/internal/sip:1200 at 192.168.4.31]
2013-11-14 14:43:55.681950 [NOTICE] switch_core_session.c:1564 Session 1471 (sofia/internal/sip:1200 at 192.168.4.30) Ended
2013-11-14 14:43:55.681950 [NOTICE] switch_core_session.c:1568 Close Channel sofia/internal/sip:1200 at 192.168.4.30 [CS_DESTROY]
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/sip:1200 at 192.168.4.30) Callstate Change HANGUP -> DOWN
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:568 (sofia/internal/sip:1200 at 192.168.4.30) Running State Change CS_DESTROY
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/sip:1200 at 192.168.4.30) State DESTROY
2013-11-14 14:43:55.681950 [DEBUG] mod_sofia.c:399 sofia/internal/sip:1200 at 192.168.4.30 SOFIA DESTROY
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:99 sofia/internal/sip:1200 at 192.168.4.30 Standard DESTROY
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/sip:1200 at 192.168.4.30) State DESTROY going to sleep
2013-11-14 14:43:55.681950 [DEBUG] switch_ivr_originate.c:3494 Originate Resulted in Success: [sofia/internal/sip:1200 at 192.168.4.31]
2013-11-14 14:43:55.681950 [DEBUG] switch_core_session.c:858 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.681950 [DEBUG] switch_core_session.c:858 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.681950 [DEBUG] switch_ivr_bridge.c:1426 (sofia/internal/sip:1200 at 192.168.4.31) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2013-11-14 14:43:55.681950 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1200 at 192.168.4.31) Running State Change CS_EXCHANGE_MEDIA
2013-11-14 14:43:55.681950 [DEBUG] switch_core_state_machine.c:480 (sofia/internal/sip:1200 at 192.168.4.31) State EXCHANGE_MEDIA
2013-11-14 14:43:55.681950 [DEBUG] mod_sofia.c:688 SOFIA EXCHANGE_MEDIA
2013-11-14 14:43:55.761950 [DEBUG] switch_rtp.c:3690 Correct ip/port confirmed.
2013-11-14 14:43:55.901950 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.901950 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.901950 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.921964 [DEBUG] sofia.c:5752 Channel sofia/internal/1401 at 192.168.4.1 entering state [ready][200]
2013-11-14 14:43:55.921964 [DEBUG] switch_core_session.c:920 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.921964 [DEBUG] switch_core_session.c:920 Send signal sofia/internal/1401 at 192.168.4.1 [BREAK]
2013-11-14 14:43:55.941972 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.941972 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1200 at 192.168.4.31 entering state [calling][0]
2013-11-14 14:43:55.941972 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.941972 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.941972 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/sip:1200 at 192.168.4.31 [BREAK]
2013-11-14 14:43:55.961964 [DEBUG] sofia.c:5752 Channel sofia/internal/sip:1200 at 192.168.4.31 entering state [ready][200]
2013-11-14 14:43:55.961964 [DEBUG] sofia.c:5762 Duplicate SDP
v=0
o=- 1384440235 1384440235 IN IP4 192.168.4.31
s=Polycom IP Phone
c=IN IP4 192.168.4.31
t=0 0
m=audio 2244 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000

2013-11-14 14:43:55.961964 [DEBUG] sofia_glue.c:5225 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-11-14 14:43:55.961964 [DEBUG] sofia_glue.c:3079 Already using PCMA
2013-11-14 14:43:55.961964 [DEBUG] sofia_glue.c:5347 Set 2833 dtmf send payload to 101
2013-11-14 14:43:55.961964 [DEBUG] sofia.c:6350 Processing updated SDP
2013-11-14 14:43:55.961964 [DEBUG] sofia_glue.c:3379 Audio params are unchanged for sofia/internal/sip:1200 at 192.168.4.31.
2013-11-14 14:43:55.961964 [DEBUG] sofia_glue.c:3389 sofia/internal/sip:1200 at 192.168.4.31 Setting audio receive payload in Re-INVITE to 8