[Freeswitch-users] FreeSWITCH PROXY:0
Asd
asdfgh1234 at freemail.hu
Fri May 15 16:47:05 MSD 2015
internal profile with disabled proxy-media <param name="inbound-proxy-media" value="false"/> what should i set my profile to internal freeswitch? my internal profile: <param name="debug" value="0"/>
<param name="sip-trace" value="no"/>
<param name="sip-capture" value="no"/>
<param name="watchdog-enabled" value="no"/>
<param name="watchdog-step-timeout" value="30000"/>
<param name="watchdog-event-timeout" value="30000"/>
<param name="log-auth-failures" value="true"/>
<param name="forward-unsolicited-mwi-notify" value="false"/>
<param name="rfc2833-pt" value="101"/>
<param name="sip-port" value="$${internal_sip_port}"/>
<param name="dialplan" value="XML"/>
<param name="dtmf-duration" value="2000"/>
<param name="inbound-codec-prefs" value="$${global_codec_prefs}"/>
<param name="outbound-codec-prefs" value="$${global_codec_prefs}"/>
<param name="rtp-ip" value="$${local_ip_v4}"/>
<param name="sip-ip" value="$${local_ip_v4}"/>
<param name="hold-music" value="$${hold_music}"/>
<param name="apply-nat-acl" value="nat.auto"/>
<param name="apply-inbound-acl" value="domains"/>
<param name="local-network-acl" value="localnet.auto"/>
<param name="context" value="sip.domain.com"/>
<param name="record-path" value="$${recordings_dir}"/>
<param name="record-template" value="${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}/${uuid}.wav"/>
<param name="presence-hosts" value="$${domain},$${local_ip_v4}"/>
<param name="presence-privacy" value="$${presence_privacy}"/>
<param name="inbound-codec-negotiation" value="generous"/>
<param name="tls" value="$${internal_ssl_enable}"/>
<param name="tls-bind-params" value="transport=tls"/>
<param name="tls-sip-port" value="$${internal_tls_port}"/>
<param name="tls-cert-dir" value="$${internal_ssl_dir}"/>
<param name="tls-passphrase" value=""/>
<param name="tls-verify-date" value="true"/>
<param name="tls-verify-in-subjects" value=""/>
<param name="tls-version" value="$${sip_tls_version}"/>
<param name="nonce-ttl" value="60"/>
<param name="auth-calls" value="$${internal_auth_calls}"/>
<param name="inbound-reg-force-matching-username" value="true"/>
<param name="ext-rtp-ip" value="$${external_rtp_ip}"/>
<param name="ext-sip-ip" value="$${external_sip_ip}"/>
<param name="rtp-timeout-sec" value="300"/>
<param name="rtp-hold-timeout-sec" value="1800"/>
<param name="force-register-domain" value="$${domain}"/>
<param name="force-subscription-domain" value="$${domain}"/>
<param name="force-register-db-domain" value="$${domain}"/>
<param name="challenge-realm" value="auto_from"/>
<param name="tls-only" value="true"/>
<param name="tls-verify-depth" value="3"/>
<param name="manage-presence" value="true"/>
<param name="rtp-timer-name" value="soft"/>
<param name="tls-ciphers" value="$${sip_tls_ciphers}"/>
<param name="aggressive-nat-detection" value="true"/>
<param name="inbound-late-negotiation" value="true"/>
<param name="inbound-zrtp-passthru" value="true"/>
<param name="tls-verify-policy" value="all"/>
<param name="send-presence-on-register" value="false"/>
<param name="auth-all-packets" value="false"/>
<param name="inbound-proxy-media" value="false"/>the log file: tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf00a2eb0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf00a2eb0)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf00a2eb0): tls_read() returned 1079
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf00a2eb0) msg 0x7fccf00a8080 from (tls/XXX.XXX.XXX.XXX:15193) has 1079 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7fccf00a2eb0): msg 0x7fccf00a8080 (1099 bytes) from tls/XXX.XXX.XXX.XXX:15193/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sips:1004 at sip.domain.com SIP/2.0 (CSeq 28198)
nta.c:3174 agent_check_request_via() nta: Via check: received=XXX.XXX.XXX.XXX
nta.c:3085 agent_recv_request() nta: INVITE (28198) going to a default leg
nta.c:1350 set_timeout() nta: timer set to 2000 ms
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:899 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7fccf0001be0, 0x7fccf0000cb0, 0x7fccf0092180) called
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf0090bc0, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fccf00a1320)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fccf0090bc0) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fccf0090bc0, (nil), 0x7fccf0091e32, 373) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fccf0092180): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x7fccf00a2eb0) tpn = TLS/XXX.XXX.XXX.XXX:15193
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf008ec40 384 (384)
tport.c:3492 tport_send_msg() tport_vsend returned 384
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (28198)
nua_session.c:4139 signal_call_state_change() nua(0x7fccf0092180): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fccf0090bc0, [0x7fcd0bdfc8b8], [0x7fcd0bdfc8c0], [(nil)]) called
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2015-05-15 13:54:57.434956 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1001 at sip.domain.com [a5330703-4ba1-48e2-bb32-649b0bd8d6c8]
2015-05-15 13:54:57.434956 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:54:57.434956 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:54:57.434956 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001 at sip.domain.com) Running State Change CS_NEW
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:54:57.434956 [DEBUG] sofia.c:8844 sofia/internal/1001 at sip.domain.com receiving invite from XXX.XXX.XXX.XXX:15193 version: 1.4.18 -3-1 64bit
2015-05-15 13:54:57.434956 [DEBUG] switch_core_media.c:344 Found audio zrtp-hash; setting r_sdp_audio_zrtp_hash=1.10 cefe05149bdf61156a54615b2de164b405ca49c2eb2b7e8adb8a09ea3f0714b0
2015-05-15 13:54:57.434956 [DEBUG] sofia.c:9011 IP XXX.XXX.XXX.XXX Rejected by acl "domains". Falling back to Digest auth.
nua.c:879 nua_respond() nua: nua_respond: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf0090bc0, ...) called
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fccf0090bc0) called
tport.c:3257 tport_tsend() tport_tsend(0x7fccf00a2eb0) tpn = TLS/XXX.XXX.XXX.XXX:15193
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf0093b30 888 (888)
tport.c:3492 tport_send_msg() tport_vsend returned 888
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nta.c:6791 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (28198)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fccf0092180): removing session usage
nua_session.c:4139 signal_call_state_change() nua(0x7fccf0092180): call state changed: received -> terminated
soa.c:356 soa_destroy() soa_destroy(static::0x7fccf0090bc0) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fccf00a1320)
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:54:57.434956 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0x7fccf0092180): sent signal r_respond
2015-05-15 13:54:57.434956 [DEBUG] sofia.c:2065 detaching session a5330703-4ba1-48e2-bb32-649b0bd8d6c8
2015-05-15 13:54:57.434956 [WARNING] sofia_reg.c:1742 SIP auth challenge (INVITE) on sofia profile 'internal' for [1004 at sip.domain.com] from ip XXX.XXX.XXX.XXX
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7fccf0092180): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
2015-05-15 13:54:57.434956 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/1001 at sip.domain.com) State NEW
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf00a2eb0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf00a2eb0)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf00a2eb0): tls_read() returned 406
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf00a2eb0) msg 0x7fccf008dfe0 from (tls/XXX.XXX.XXX.XXX:15193) has 406 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7fccf00a2eb0): msg 0x7fccf008dfe0 (406 bytes) from tls/XXX.XXX.XXX.XXX:15193/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sips:1004 at sip.domain.com SIP/2.0 (CSeq 28198)
nta.c:3174 agent_check_request_via() nta: Via check: received=XXX.XXX.XXX.XXX
nta.c:3019 agent_recv_request() nta: ACK (28198) is going to INVITE (28198)
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf00a2eb0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf00a2eb0)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf00a2eb0): tls_read() returned 1350
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf00a2eb0) msg 0x7fccf008dfe0 from (tls/XXX.XXX.XXX.XXX:15193) has 1350 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7fccf00a2eb0): msg 0x7fccf008dfe0 (1350 bytes) from tls/XXX.XXX.XXX.XXX:15193/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sips:1004 at sip.domain.com SIP/2.0 (CSeq 28199)
nta.c:3174 agent_check_request_via() nta: Via check: received=XXX.XXX.XXX.XXX
nta.c:3085 agent_recv_request() nta: INVITE (28199) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:899 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7fccf0001be0, 0x7fccf0000cb0, 0x7fccf0091540) called
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf0091660, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fccf0093530)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fccf0091660) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fccf0091660, (nil), 0x7fccf0092551, 373) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fccf0091540): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x7fccf00a2eb0) tpn = TLS/XXX.XXX.XXX.XXX:15193
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf008c970 384 (384)
tport.c:3492 tport_send_msg() tport_vsend returned 384
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (28199)
nua_session.c:4139 signal_call_state_change() nua(0x7fccf0091540): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fccf0091660, [0x7fcd0bdfc8b8], [0x7fcd0bdfc8c0], [(nil)]) called
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2015-05-15 13:54:57.614920 [DEBUG] sofia.c:2173 Re-attaching to session a5330703-4ba1-48e2-bb32-649b0bd8d6c8
2015-05-15 13:54:57.614920 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:54:57.614920 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:54:57.634956 [DEBUG] sofia.c:8844 sofia/internal/1001 at sip.domain.com receiving invite from XXX.XXX.XXX.XXX:15193 version: 1.4.18 -3-1 64bit
2015-05-15 13:54:57.634956 [DEBUG] switch_core_media.c:344 Found audio zrtp-hash; setting r_sdp_audio_zrtp_hash=1.10 cefe05149bdf61156a54615b2de164b405ca49c2eb2b7e8adb8a09ea3f0714b0
2015-05-15 13:54:57.634956 [DEBUG] sofia.c:9011 IP XXX.XXX.XXX.XXX Rejected by acl "domains". Falling back to Digest auth.
nua.c:610 nua_set_hparams() nua: nua_set_hparams: entering
nua.c:610 nua_set_hparams() nua: nua_r_set_params with invalid handle (nil)
2015-05-15 13:54:57.634956 [DEBUG] sofia.c:10109 Setting NAT mode based on via received
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:54:57.634956 [DEBUG] sofia.c:6623 Channel sofia/internal/1001 at sip.domain.com entering state [received][100]
2015-05-15 13:54:57.634956 [DEBUG] sofia.c:6633 Remote SDP:
v=0
o=- 3640679697 3640679697 IN IP4 192.168.51.35
s=pjmedia
c=IN IP4 192.168.51.35
t=0 0
m=audio 4000 RTP/AVP 8 3 101
c=IN IP4 192.168.51.35
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp:4001 IN IP4 192.168.51.35
a=zrtp-hash:1.10 cefe05149bdf61156a54615b2de164b405ca49c2eb2b7e8adb8a09ea3f0714b0 2015-05-15 13:54:57.634956 [DEBUG] sofia.c:6899 (sofia/internal/1001 at sip.domain.com) State Change CS_NEW -> CS_INIT
2015-05-15 13:54:57.634956 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001 at sip.domain.com) Running State Change CS_INIT
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1001 at sip.domain.com) State INIT
2015-05-15 13:54:57.634956 [DEBUG] mod_sofia.c:87 sofia/internal/1001 at sip.domain.com SOFIA INIT
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001 at sip.domain.com Standard INIT
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001 at sip.domain.com) State Change CS_INIT -> CS_ROUTING
2015-05-15 13:54:57.634956 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1001 at sip.domain.com) State INIT going to sleep
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001 at sip.domain.com) Running State Change CS_ROUTING
2015-05-15 13:54:57.634956 [DEBUG] switch_channel.c:2184 (sofia/internal/1001 at sip.domain.com) Callstate Change DOWN -> RINGING
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1001 at sip.domain.com) State ROUTING
2015-05-15 13:54:57.634956 [DEBUG] mod_sofia.c:123 sofia/internal/1001 at sip.domain.com SOFIA ROUTING
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:166 sofia/internal/1001 at sip.domain.com Standard ROUTING
2015-05-15 13:54:57.634956 [INFO] mod_dialplan_xml.c:635 Processing 1001 <1001>->1004 in context sip.domain.com
Dialplan: sofia/internal/1001 at sip.domain.com parsing [sip.domain.com->PHONE-FAX_b_1001_49123456789100] continue=false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (PASS) [PHONE-FAX_b_1001_49123456789100] context(sip.domain.com) =~ /sip.domain.com/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (FAIL) [PHONE-FAX_b_1001_49123456789100] destination_number(1004) =~ /^(1234567e0)$/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com parsing [sip.domain.com->PHONE-FAX_l_1002_49123456789101] continue=false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (PASS) [PHONE-FAX_l_1002_49123456789101] context(sip.domain.com) =~ /sip.domain.com/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (FAIL) [PHONE-FAX_l_1002_49123456789101] destination_number(1004) =~ /^(1234567e1)$/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com parsing [sip.domain.com->PHONE-FAX_m_1003_49123456789101-copy] continue=false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (PASS) [PHONE-FAX_m_1003_49123456789101-copy] context(sip.domain.com) =~ /sip.domain.com/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (FAIL) [PHONE-FAX_m_1003_49123456789101-copy] destination_number(1004) =~ /^(1234567e2)$/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com parsing [sip.domain.com->internal-voicemail-com] continue=false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (PASS) [internal-voicemail-com] context(sip.domain.com) =~ /sip.domain.com/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (PASS) [internal-voicemail-com] caller_id_number(1001) =~ /^(((\+|00)YY)|1\d{3})$/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (FAIL) [internal-voicemail-com] ${user_data(${destination_number}@${domain} param vm-enabled)}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com parsing [sip.domain.com->internal-voicemail-de] continue=false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (PASS) [internal-voicemail-de] context(sip.domain.com) =~ /sip.domain.com/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (FAIL) [internal-voicemail-de] ${user_data(${destination_number}@${domain} param vm-enabled)}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com parsing [sip.domain.com->internal] continue=false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (PASS) [internal] context(sip.domain.com) =~ /sip.domain.com/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com Regex (PASS) [internal] destination_number(1004) =~ /^(1\d{3})$/ break=on-false
Dialplan: sofia/internal/1001 at sip.domain.com Action set(zrtp_enrollment=true)
Dialplan: sofia/internal/1001 at sip.domain.com Action set(hangup_after_bridge=false)
Dialplan: sofia/internal/1001 at sip.domain.com Action set(continue_on_fail=true)
Dialplan: sofia/internal/1001 at sip.domain.com Action set(intcallid=1004)
Dialplan: sofia/internal/1001 at sip.domain.com Action bridge(sofia/internal/${intcallid}%${domain})
Dialplan: sofia/internal/1001 at sip.domain.com Action set(eml=${user_data(${intcallid}@${domain} param vm-mailto)})
Dialplan: sofia/internal/1001 at sip.domain.com Action set(datetime=${strftime(%Y.%m.%d)} | ${strftime(%W)}. HET | ${strftime(%H:%M)})
Dialplan: sofia/internal/1001 at sip.domain.com Action set(smtp_from=root)
Dialplan: sofia/internal/1001 at sip.domain.com Action lua(NoAns.lua '${originate_disposition}' '${eml}' '${smtp_from}' 'aaa' 'bbb' 'ccc')
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:216 (sofia/internal/1001 at sip.domain.com) State Change CS_ROUTING -> CS_EXECUTE
2015-05-15 13:54:57.634956 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1001 at sip.domain.com) State ROUTING going to sleep
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001 at sip.domain.com) Running State Change CS_EXECUTE
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/1001 at sip.domain.com) State EXECUTE
2015-05-15 13:54:57.634956 [DEBUG] mod_sofia.c:178 sofia/internal/1001 at sip.domain.com SOFIA EXECUTE
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:258 sofia/internal/1001 at sip.domain.com Standard EXECUTE
EXECUTE sofia/internal/1001 at sip.domain.com set(zrtp_enrollment=true)
2015-05-15 13:54:57.634956 [DEBUG] mod_dptools.c:1445 sofia/internal/1001 at sip.domain.com SET [zrtp_enrollment]=[true]
EXECUTE sofia/internal/1001 at sip.domain.com set(hangup_after_bridge=false)
2015-05-15 13:54:57.634956 [DEBUG] mod_dptools.c:1445 sofia/internal/1001 at sip.domain.com SET [hangup_after_bridge]=[false]
EXECUTE sofia/internal/1001 at sip.domain.com set(continue_on_fail=true)
2015-05-15 13:54:57.634956 [DEBUG] mod_dptools.c:1445 sofia/internal/1001 at sip.domain.com SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1001 at sip.domain.com set(intcallid=1004)
2015-05-15 13:54:57.634956 [DEBUG] mod_dptools.c:1445 sofia/internal/1001 at sip.domain.com SET [intcallid]=[1004]
EXECUTE sofia/internal/1001 at sip.domain.com bridge(sofia/internal/1004%sip.domain.com)
2015-05-15 13:54:57.634956 [DEBUG] switch_channel.c:1201 sofia/internal/1001 at sip.domain.com EXPORTING[export_vars] [domain_name]=[sip.domain.com] to event
2015-05-15 13:54:57.634956 [DEBUG] switch_ivr_originate.c:2100 Parsing global variables
2015-05-15 13:54:57.634956 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1004 [e6f3933c-e8f7-4590-af6c-4de82995ee46]
2015-05-15 13:54:57.634956 [DEBUG] mod_sofia.c:4701 (sofia/internal/1004) State Change CS_NEW -> CS_INIT
2015-05-15 13:54:57.634956 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1004 [BREAK]
2015-05-15 13:54:57.634956 [DEBUG] switch_core_media.c:266 Passing a-leg remote zrtp-hash (audio) to b-leg
2015-05-15 13:54:57.634956 [DEBUG] mod_sofia.c:4771 [zrtp_passthru] Setting a-leg inherit_codec=true
2015-05-15 13:54:57.634956 [DEBUG] mod_sofia.c:4774 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMA at 8000h@20i at 64000b,GSM at 8000h@20i at 13200b'
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004) Running State Change CS_INIT
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1004) State INIT
2015-05-15 13:54:57.634956 [DEBUG] mod_sofia.c:87 sofia/internal/1004 SOFIA INIT
2015-05-15 13:54:57.634956 [DEBUG] switch_core_media.c:6137 Adding audio a=zrtp-hash:1.10 cefe05149bdf61156a54615b2de164b405ca49c2eb2b7e8adb8a09ea3f0714b0
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2015-05-15 13:54:57.634956 [DEBUG] sofia_glue.c:1203 sip:1004 at XXX.XXX.XXX.XXX:15194;transport=tls;registering_acc=sip_domain_com Setting proxy route to sofia/internal/1004
2015-05-15 13:54:57.634956 [DEBUG] sofia_glue.c:1232 sofia/internal/1004 sending invite version: 1.4.18 -3-1 64bit
Local SDP:
v=0
o=FreeSWITCH 1431670287 1431670288 IN IP4 YYY.YYY.YYY.YYY
s=FreeSWITCH
c=IN IP4 YYY.YYY.YYY.YYY
t=0 0
m=audio 20610 RTP/AVP 8 3 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=zrtp-hash:1.10 cefe05149bdf61156a54615b2de164b405ca49c2eb2b7e8adb8a09ea3f0714b0
a=sendrecv nua.c:633 nua_invite() nua: nua_invite: entering
nua_stack.c:529 nua_signal() nua(0x7fcccc00a070): sent signal r_invite
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1004 Standard INIT
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1004) State Change CS_INIT -> CS_ROUTING
2015-05-15 13:54:57.634956 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1004 [BREAK]
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1004) State INIT going to sleep
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7fccf0001be0, 0x7fccf0000cb0, 0x7fcccc00a070) called
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf008b650, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf008b650, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fccf008b650, (nil), 0x7fcccc0062b6, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fccf008b650, (nil), 0x7fcccc0062b6, -1) called
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004) Running State Change CS_ROUTING
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fcccc00a070): adding session usage
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fccf00b0bb0)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fccf008b650) called
soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fccf008b650, 0) called
soa_static.c:1146 offer_answer_step() soa_static_offer_answer_action(0x7fccf008b650, soa_generate_offer): called
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1004) State ROUTING
soa_static.c:1187 offer_answer_step() soa_static(0x7fccf008b650, soa_generate_offer): generating local description
soa_static.c:1215 offer_answer_step() soa_static(0x7fccf008b650, soa_generate_offer): upgrade with local description
2015-05-15 13:54:57.634956 [DEBUG] mod_sofia.c:123 sofia/internal/1004 SOFIA ROUTING
2015-05-15 13:54:57.634956 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1004) State Change CS_ROUTING -> CS_CONSUME_MEDIA
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fcd0bdfaa70, (nil), ""): called
2015-05-15 13:54:57.634956 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1004 [BREAK]
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1004) State ROUTING going to sleep
soa_static.c:1444 offer_answer_step() soa_static(0x7fccf008b650, soa_generate_offer): storing local description
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fccf008b650, [(nil)], [0x7fcd0bdfcbf8], [0x7fcd0bdfcbf4]) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:4588 tport_by_name() tport(0x7fccf0004620): found 0x7fccf0077460 by name tls/XXX.XXX.XXX.XXX:15194
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004) Running State Change CS_CONSUME_MEDIA
tport.c:3257 tport_tsend() tport_tsend(0x7fccf0077460) tpn = tls/XXX.XXX.XXX.XXX:15194
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/1004) State CONSUME_MEDIA
2015-05-15 13:54:57.634956 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/1004) State CONSUME_MEDIA going to sleep
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0057610 0x7fccf00b3af0 1018 (1018)
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0057610 0x7fccf00b13f0 90 (90)
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0057610 0x7fccf00b2ff0 333 (333)
tport.c:3492 tport_send_msg() tport_vsend returned 1441
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf0077460): reset timer
nta.c:8304 outgoing_send() nta: sent INVITE (75509384) to tls/XXX.XXX.XXX.XXX:15194
tport.c:4160 tport_pend() tport_pend(0x7fccf0077460): pending 0x7fccf00b1040 for tls/XXX.XXX.XXX.XXX:15194 (already 0)
nua_session.c:4139 signal_call_state_change() nua(0x7fcccc00a070): call state changed: init -> calling, sent offer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fccf008b650, [0x7fcd0bdfcbd8], [0x7fcd0bdfcbe0], [(nil)]) called
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:54:57.634956 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1004 [BREAK]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:54:57.634956 [DEBUG] sofia.c:6623 Channel sofia/internal/1004 entering state [calling][0]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf0077460): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf0077460)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf0077460): tls_read() returned 1
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf0077460) msg 0x7fccf00b40c0 from (tls/XXX.XXX.XXX.XXX:15194) has 1 bytes, veclen = 1
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf0077460): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf0077460): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf0077460)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf0077460): tls_read() returned 497
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf0077460) msg 0x7fccf00b40c0 from (tls/XXX.XXX.XXX.XXX:15194) has 497 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7fccf0077460): msg 0x7fccf00b40c0 (498 bytes) from tls/XXX.XXX.XXX.XXX:15194/sips next=(nil)
nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (75509384)
nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 180.054 ms
tport.c:4222 tport_release() tport_release(0x7fccf0077460): 0x7fccf00b1040 by 0x7fccf00b3150 with 0x7fccf00b40c0 (preliminary)
nua_session.c:4139 signal_call_state_change() nua(0x7fcccc00a070): call state changed: calling -> proceeding
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf0077460): reset timer
2015-05-15 13:54:57.814956 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1004 [BREAK]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:54:57.814956 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1004 [BREAK]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:54:57.814956 [DEBUG] sofia.c:6623 Channel sofia/internal/1004 entering state [proceeding][180]
2015-05-15 13:54:57.814956 [NOTICE] sofia.c:6725 Ring-Ready sofia/internal/1004!
2015-05-15 13:54:57.814956 [DEBUG] switch_channel.c:3277 (sofia/internal/1004) Callstate Change DOWN -> RINGING
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:54:57.854927 [INFO] switch_ivr_originate.c:1192 Sending early media
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:344 Found audio zrtp-hash; setting r_sdp_audio_zrtp_hash=1.10 cefe05149bdf61156a54615b2de164b405ca49c2eb2b7e8adb8a09ea3f0714b0
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:266 Passing a-leg remote zrtp-hash (audio) to b-leg
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:3632 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:3687 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:3632 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:3632 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:3632 Audio Codec Compare [GSM:3:8000:20:13200:1]/[GSM:3:8000:20:13200:1]
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:3687 Audio Codec Compare [GSM:3:8000:20:13200:1] ++++ is saved as a match
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:3548 Set telephone-event payload to 101
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:2473 Set Codec sofia/internal/1001 at sip.domain.com PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2015-05-15 13:54:57.854927 [DEBUG] switch_core_codec.c:111 sofia/internal/1001 at sip.domain.com Original read codec set to PCMA:8
2015-05-15 13:54:57.854927 [DEBUG] switch_core_media.c:3895 Set 2833 dtmf send/recv payload to 101
2015-05-15 13:54:57.874951 [DEBUG] switch_core_media.c:5147 AUDIO RTP [sofia/internal/1001 at sip.domain.com] YYY.YYY.YYY.YYY port 20514 -> 192.168.51.35 port 4000 codec: 8 ms: 20
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:3562 Starting timer [soft] 160 bytes per 20ms
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: START SESSION INITIALIZATION. sID=4.
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: ZID=346661636436616664366363.
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Loading User's profile:
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: allowclear: OFF
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: autosecure: ON
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: disclose_bit: OFF
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: signal. role: Unknown
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: TTL: 4294967295
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: SAS schemes:
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 B256
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 B32
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Ciphers:
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 AES3
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 AES1
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: PK schemes:
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 EC25
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 DH3k
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 DH2k
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 Mult
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: ATL:
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 HS32
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Hashes:
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 S256
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Session initialization - DONE. sID=4.2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: ATTACH NEW STREAM to sID=4:
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>.
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Empty slot was found - initializing new stream with ID=4.
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Preparing ZRTP Hello according to the Session profile.
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp main]: ATTACH NEW STREAM - DONE.
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp mitm]: START REGISTRATION STREAM ID=4 mode=CLEAR state=ACTIVE.
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: START STREAM ID=4 mode=CLEAR state=ACTIVE.
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=4 CLEAR switching <ACTIVE> ---> <START>.
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <HELLO> ssrc=2237203113 seq=28453 size=144. Stream 4:CLEAR:START
2015-05-15 13:54:57.874951 [INFO] switch_core_media.c:5364 Activating RTCP PORT 4001
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:3912 RTCP send rate is: 5000 and packet rate is: 20000 Remote Port: 4001
2015-05-15 13:54:57.874951 [DEBUG] switch_rtp.c:2367 Setting RTCP remote addr to 192.168.51.35:4001
2015-05-15 13:54:57.874951 [DEBUG] switch_core_media.c:5445 Set 2833 dtmf send payload to 101
2015-05-15 13:54:57.874951 [DEBUG] switch_core_media.c:5451 Set 2833 dtmf receive payload to 101
2015-05-15 13:54:57.874951 [INFO] switch_channel.c:3321 sofia/internal/1001 at sip.domain.com ZRTP not negotiated on both sides; disabling ZRTP passthru mode.
2015-05-15 13:54:57.874951 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1001 at sip.domain.com!
2015-05-15 13:54:57.874951 [DEBUG] switch_channel.c:3399 (sofia/internal/1001 at sip.domain.com) Callstate Change RINGING -> EARLY
2015-05-15 13:54:57.874951 [DEBUG] mod_sofia.c:2268 Ring SDP:
v=0
o=FreeSWITCH 1431670383 1431670384 IN IP4 YYY.YYY.YYY.YYY
s=FreeSWITCH
c=IN IP4 YYY.YYY.YYY.YYY
t=0 0
m=audio 20514 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
a=rtcp:20515 IN IP4 YYY.YYY.YYY.YYY nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7fccf0091540): sent signal r_respond
2015-05-15 13:54:57.874951 [DEBUG] switch_core_session.c:912 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:54:57.874951 [DEBUG] switch_ivr_originate.c:1249 Raw Codec Activation Success L16 at 8000hz 1 channel 20ms
2015-05-15 13:54:57.874951 [DEBUG] switch_core_codec.c:221 sofia/internal/1001 at sip.domain.com Push codec L16:100
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf0091660, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fccf0091660, (nil), 0x7fcd30003af8, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fccf0091660, (nil), 0x7fcd30003af8, -1) called
2015-05-15 13:54:57.874951 [DEBUG] switch_ivr_originate.c:1317 Play Ringback Tone [%(1000,4000,425,0)]
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7fccf0091660) called
soa_static.c:1146 offer_answer_step() soa_static_offer_answer_action(0x7fccf0091660, soa_generate_answer): called
soa_static.c:1187 offer_answer_step() soa_static(0x7fccf0091660, soa_generate_answer): generating local description
soa_static.c:1228 offer_answer_step() soa_static(0x7fccf0091660, soa_generate_answer): upgrade with remote description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fcd0bdfaab0, 0x7fccf008b8c0, ""): called
soa_static.c:1444 offer_answer_step() soa_static(0x7fccf0091660, soa_generate_answer): storing local description
soa.c:1730 soa_activate() soa_activate(static::0x7fccf0091660, (nil)) called
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fccf0091660, [(nil)], [0x7fcd0bdfcc38], [0x7fcd0bdfcc34]) called
tport.c:3257 tport_tsend() tport_tsend(0x7fccf00a2eb0) tpn = TLS/XXX.XXX.XXX.XXX:15193
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf00b8780 956 (956)
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf00b7e30 260 (260)
tport.c:3492 tport_send_msg() tport_vsend returned 1216
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nta.c:6791 incoming_reply() nta: sent 183 Session Progress for INVITE (28199)
nua_session.c:4139 signal_call_state_change() nua(0x7fccf0091540): call state changed: received -> early, sent answer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fccf0091660, [0x7fcd0bdfcce8], [0x7fcd0bdfccf0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7fccf0091660, ...) called
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:54:57.874951 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:54:57.894987 [DEBUG] sofia.c:6623 Channel sofia/internal/1001 at sip.domain.com entering state [early][183]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:54:57.934958 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <HELLO> ssrc=2237203113 seq=28454 size=144. Stream 4:CLEAR:START
2015-05-15 13:54:57.994988 [DEBUG] switch_rtp.c:1955 rtcp_stats_init: ssrc[644801348] base_seq[30552]
2015-05-15 13:54:58.014989 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <HELLO> ssrc=2237203113 seq=28455 size=144. Stream 4:CLEAR:START
2015-05-15 13:54:58.155010 [INFO] switch_rtp.c:5846 Auto Changing port from 192.168.51.35:4000 to XXX.XXX.XXX.XXX:14554
2015-05-15 13:54:58.155010 [DEBUG] switch_rtp.c:2367 Setting RTCP remote addr to XXX.XXX.XXX.XXX:14555
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Received <Hello > packet with ssrc=644801348 seq=1/1 size=168. Stream4:CLEAR:START.
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Processing HELLO from PJS ZRTP 3.0.0 V=1.10, P=0, M=0.
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: ac=4 cc=4 sc=1 kc=5
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: S384S2562FS3AES32FS1AES1SK32SK64HS32HS80EC25DH3kEC38DH2kMultB32
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Received HELLO had the same protocol V.
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: _zrtp_choose_best_comp() for PKT. local=EC25 remote=EC25, choosen=EC25
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Received HELLO Accepted
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: ache_get(): zid1=346661636436616664366363, zis2=1b1f26a336ab4d86859e557d MiTM=NO
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: ache_get(): zid1=346661636436616664366363, zis2=1b1f26a336ab4d86859e557d MiTM=NO
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: ache_get(): zid1=346661636436616664366363, zis2=1b1f26a336ab4d86859e557d MiTM=YES
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Restoring Secrets: lZID=346661636436616664366363 rZID=1b1f26a336ab4d86859e557d. V=1 sID=4
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: RS1 <8b9b28eb023b7ddc32ef8690ddf28649115d721b22be9d81f24b772184093b6d>
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: RS2 <523e305c538d5e2c5b971ab21d1a29ad378bef1615515130e022735fe25006bd>
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: PBX <9d3658c6a665804d913f7b8552897605ed76c691a081332a5ff9d4d441abf482>
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <HELLOACK> ssrc=2237203113 seq=28456 size=28. Stream 4:CLEAR:START
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=4 CLEAR switching <START> ---> <W4HACK>.
2015-05-15 13:54:58.234936 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <HELLO> ssrc=2237203113 seq=28457 size=144. Stream 4:CLEAR:W4HACK
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1955 rtcp_stats_init: ssrc[644801348] base_seq[2]
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Received <HelloACK> packet with ssrc=644801348 seq=2/2 size=28. Stream4:CLEAR:W4HACK.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=4 CLEAR switching <W4HACK> ---> <SINITSEC>.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Initiating Secure iteration... ID=4.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Got mode=DH. Check approval of starting.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Mode=DH Cccepted. Starting ZRTP Initiator Protocol.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: ENTER STATE INITIATING SECURE for ID=4 mode=DH state=SINITSEC.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: Initiator selected following options:
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: Hash: S256
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: Cipher: AES3
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: ATL: HS32
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: VAD scheme: B32
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Init INITIATOR's Protocol ID=4 mode=DH...
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [ zrtp ecdh]: DH TEST: zrtp_ecdh_initialize() for EC25 was executed by 10ms.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Attach RS id=e616852a885a3e89.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Attach RS peer_id=4aa5f81d3b9b6f2e.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Attach RS id=4cd99f03438d3ebc.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Attach RS peer_id=b9bf9e8c9f89cc58.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Attach RS id=ecf6dd533343a217.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Attach RS peer_id=15d7a9d63a9da7f8.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Attach RS id=c9bad87c4fb5bb8b.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Attach RS peer_id=1695ac21336ec842.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=4 DH switching <SINITSEC> ---> <INITSEC>.
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: Start Sending COMMIT ID=4 mode=DH state=INITSEC:
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: Hash: S256
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: Cipher: AES3
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: ATL: HS32
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: PK scheme: EC25
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: VAD scheme: B32
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [zrtp initiat]: hv: 9b03f61329f4e5badc74b034b0dfde4615eacb5a8a9b68d5ecf3194ea20bf45d
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <COMMIT> ssrc=2237203113 seq=28458 size=132. Stream 4:DH:INITSEC
2015-05-15 13:54:58.334911 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.354913 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.374938 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.394966 [DEBUG] switch_rtp.c:1955 rtcp_stats_init: ssrc[644801348] base_seq[30570]
2015-05-15 13:54:58.394966 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.394966 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Received <DHPart1 > packet with ssrc=644801348 seq=3/3 size=164. Stream4:DH:INITSEC.
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [ zrtp ecdh]: DH TEST: zrtp_ecdh_validate() for EC25 was executed by 0ms.
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <DH2> ssrc=2237203113 seq=28459 size=164. Stream 4:DH:INITSEC
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: ---------------------------------------------------
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: SWITCHING TO SRTP. ID=1092774504
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: I Initiator
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: DERIVE S0 from DH exchange and RS secrets...
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: my rs1ID:e616852a885a3e89
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: his rs1ID:4aa5f81d3b9b6f2e
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: his rs1ID comp:4aa5f81d3b9b6f2e
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: my rs2ID:4cd99f03438d3ebc
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: his rs2ID:41ee3d31e442e2db
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: his rs2ID comp:b9bf9e8c9f89cc58
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: my pbxsID:c9bad87c4fb5bb8b
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: his pbxsID:f7d894dc7a1b0333
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: his pbxsID comp:1695ac21336ec842
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: ECDH comp_length=32
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [ zrtp ecdh]: DH TEST: zrtp_ecdh_compute() for EC25 was executed by 9ms.
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Use S1 in calculations.
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=4 DH switching <INITSEC> ---> <WCONFIRM>.
2015-05-15 13:54:58.434968 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.475050 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.494970 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.514973 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.514973 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.554962 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.554962 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1955 rtcp_stats_init: ssrc[644801348] base_seq[4]
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Received <Confirm1> packet with ssrc=644801348 seq=4/4 size=92. Stream4:DH:WCONFIRM.
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=4 DH switching <WCONFIRM> ---> <W4CONFACK>.
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: HMAC TRACE. COMPUTE.
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: cipher text:593352f2f8a9e76f6c2f61f8cb5f4cc9e2627db9fa2e660a198a30fe7f529e847829a83d11b9ca66. size=40
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: key:24626b9d001ba9aafc3be5c9cdc872753f5d109589e4e0a3e2d22c3ffd77068a.
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: comp hmac:9d4563b8b476288993c4ae0cd340a8da6267ffec857580c1949e0ee025ed0ef7.
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: hmac:9d4563b8b4762889.
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <CONFIRM2> ssrc=2237203113 seq=28460 size=92. Stream 4:DH:W4CONFACK
2015-05-15 13:54:58.594931 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.614967 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: ERROR! Decrypt failed. ID=4:DH s=SRTP authentication failure (RTP size=172 ssrc=644801348 seq=30579/30579 pt=8)
2015-05-15 13:54:58.614967 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.614967 [DEBUG] switch_rtp.c:1955 rtcp_stats_init: ssrc[644801348] base_seq[30580]
2015-05-15 13:54:58.614967 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: ERROR! Decrypt failed. ID=4:DH s=SRTP authentication failure (RTP size=172 ssrc=644801348 seq=30580/30580 pt=8)
2015-05-15 13:54:58.614967 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.654948 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: ERROR! Decrypt failed. ID=4:DH s=SRTP authentication failure (RTP size=172 ssrc=644801348 seq=30581/30581 pt=8)
2015-05-15 13:54:58.654948 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.674985 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: ERROR! Decrypt failed. ID=4:DH s=SRTP authentication failure (RTP size=172 ssrc=644801348 seq=30582/30582 pt=8)
2015-05-15 13:54:58.674985 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.694967 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: ERROR! Decrypt failed. ID=4:DH s=SRTP authentication failure (RTP size=172 ssrc=644801348 seq=30583/30583 pt=8)
2015-05-15 13:54:58.694967 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.694967 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: ERROR! Decrypt failed. ID=4:DH s=SRTP authentication failure (RTP size=172 ssrc=644801348 seq=30584/30584 pt=8)
2015-05-15 13:54:58.694967 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.734933 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: ERROR! Decrypt failed. ID=4:DH s=SRTP authentication failure (RTP size=172 ssrc=644801348 seq=30585/30585 pt=8)
2015-05-15 13:54:58.734933 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool.
2015-05-15 13:54:58.734933 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <CONFIRM2> ssrc=2237203113 seq=28461 size=92. Stream 4:DH:W4CONFACK
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Received <Conf2ACK> packet with ssrc=644801348 seq=5/5 size=28. Stream4:DH:W4CONFACK.
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Enter state SECURE (DH).
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: This is the very first stream in sID GENERATING SAS value.
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: SAS computed: <45zt> <>.
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Check expiration interval: last_use=1431564469 ttl=4294967295 new_ttl=4294967295 exp=1431564468 now=1431690898
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: Flags C=26 M=2 W=0 ID=4
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=4 DH switching <W4CONFACK> ---> <SECURE>.
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: Storing ZRTP cache to </var/lib/freeswitch/db/zrtp.dat>...
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: INFO! The user requires new un-enrolment - the nedpint may clear the cache or perform other action. ID=4
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1341 User unenrolled!
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: INFO! The user requires new enrolment - generate new MiTM secret. ID=4
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp mitm]: MARKING this call as REGISTRATION ID=4
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: cache_put() zid1=346661636436616664366363, zis2=1b1f26a336ab4d86859e557d MiTM=YES
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: cache_put() Just update existing value.
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: Storing ZRTP cache to </var/lib/freeswitch/db/zrtp.dat>...
2015-05-15 13:54:58.754926 [DEBUG] switch_core_sqldb.c:2599 Secure Type: zrtp:45zt:
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: 1 out of 1 MiTM cache entries have been flushed successfully.
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp mitm]: Makring this call as REGISTRATION - DONE
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1334 New user enrolled!
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: cache_put() zid1=346661636436616664366363, zis2=1b1f26a336ab4d86859e557d MiTM=NO
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: cache_put() Just update existing value.
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: Storing ZRTP cache to </var/lib/freeswitch/db/zrtp.dat>...
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: 1 out of 3 regular cache entries have been flushed successfully.
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: New secret was generated:
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: RS1 value:<c450a01dfff94ed1e4f06c0171cfc2a63ec32c0e43535a6782b814afb96d4dfa>
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [zrtp protoco]: TTL=4294967295, flags C=26 M=22 W=0 V=1
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: Storing ZRTP cache to </var/lib/freeswitch/db/zrtp.dat>...
2015-05-15 13:54:58.754926 [DEBUG] switch_rtp.c:1370 [ zrtp cache]: 1 out of 3 regular cache entries have been flushed successfully.
2015-05-15 13:54:58.915009 [DEBUG] switch_rtp.c:1955 rtcp_stats_init: ssrc[644801348] base_seq[6]
2015-05-15 13:54:58.915009 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Received <Conf2ACK> packet with ssrc=644801348 seq=6/6 size=28. Stream4:DH:SECURE.
2015-05-15 13:54:58.974962 [DEBUG] switch_rtp.c:1955 rtcp_stats_init: ssrc[644801348] base_seq[30595]
nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fcd0bdfcc60)
nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 0/0 term, 1/2 free
nta.c:1296 agent_timer() nta: timer set next to 58413 ms
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf0077460): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf0077460)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf0077460): tls_read() returned 1
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf0077460) msg 0x7fccf00a8080 from (tls/XXX.XXX.XXX.XXX:15194) has 1 bytes, veclen = 1
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf0077460): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf0077460): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf0077460)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf0077460): tls_read() returned 678
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf0077460) msg 0x7fccf00a8080 from (tls/XXX.XXX.XXX.XXX:15194) has 678 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7fccf0077460): msg 0x7fccf00a8080 (679 bytes) from tls/XXX.XXX.XXX.XXX:15194/sips next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (75509384)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
tport.c:4222 tport_release() tport_release(0x7fccf0077460): 0x7fccf00b1040 by 0x7fccf00b3150 with 0x7fccf00a8080
nta.c:1348 set_timeout() nta: timer shortened to 32000 ms
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fccf008b650, (nil), 0x7fccf0092c9e, 153) called
soa.c:1595 soa_process_answer() soa_process_answer(static::0x7fccf008b650) called
soa_static.c:1146 offer_answer_step() soa_static_offer_answer_action(0x7fccf008b650, soa_process_answer): called
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fccf00b2620, 0x7fccf00a1400, ""): called
soa_static.c:1302 offer_answer_step() soa_static(0x7fccf008b650, soa_process_answer): upgrade codecs with remote description
soa.c:1730 soa_activate() soa_activate(static::0x7fccf008b650, (nil)) called
nua_session.c:988 nua_session_client_response() nua(0x7fcccc00a070): INVITE: processed SDP answer in 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_session.c:4139 signal_call_state_change() nua(0x7fcccc00a070): call state changed: proceeding -> completing, received answer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fccf008b650, [0x7fcd0bdfc5d8], [0x7fcd0bdfc5e0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7fccf008b650, ...) called
2015-05-15 13:55:05.694950 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1004 [BREAK]
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf0077460): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:55:05.694950 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1004 [BREAK]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:55:05.694950 [DEBUG] switch_core_media.c:272 Passing b-leg remote zrtp-hash (audio) to a-leg
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:55:05.694950 [DEBUG] sofia.c:6623 Channel sofia/internal/1004 entering state [completing][200]
2015-05-15 13:55:05.694950 [DEBUG] sofia.c:6633 Remote SDP:
v=0
o=1004-jitsi.org 0 0 IN IP4 192.168.51.31
s=-
c=IN IP4 192.168.51.31
t=0 0
m=audio 5000 RTP/AVP 8 3
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000 nua.c:639 nua_ack() nua: nua_ack: entering
nua_stack.c:529 nua_signal() nua(0x7fcccc00a070): sent signal r_ack
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf008b650, ...) called
soa.c:1730 soa_activate() soa_activate(static::0x7fccf008b650, (nil)) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:4588 tport_by_name() tport(0x7fccf0004620): found 0x7fccf0077460 by name tls/XXX.XXX.XXX.XXX:15194
tport.c:3257 tport_tsend() tport_tsend(0x7fccf0077460) tpn = tls/XXX.XXX.XXX.XXX:15194
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0057610 0x7fccf00aaf20 475 (475)
tport.c:3492 tport_send_msg() tport_vsend returned 475
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf0077460): reset timer
nta.c:8304 outgoing_send() nta: sent ACK (75509384) to tls/XXX.XXX.XXX.XXX:15194
nua_session.c:4139 signal_call_state_change() nua(0x7fcccc00a070): call state changed: completing -> ready
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:55:05.694950 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1004 [BREAK]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:55:05.694950 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1004 [BREAK]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:55:05.714923 [DEBUG] sofia.c:6623 Channel sofia/internal/1004 entering state [ready][200]
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:272 Passing b-leg remote zrtp-hash (audio) to a-leg
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:3632 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:3687 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:3632 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:3632 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:3632 Audio Codec Compare [GSM:3:8000:20:13200:1]/[GSM:3:8000:20:13200:1]
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:3687 Audio Codec Compare [GSM:3:8000:20:13200:1] ++++ is saved as a match
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:2473 Set Codec sofia/internal/1004 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2015-05-15 13:55:05.714923 [DEBUG] switch_core_codec.c:111 sofia/internal/1004 Original read codec set to PCMA:8
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:3908 No 2833 in SDP. Disable 2833 dtmf and switch to INFO
2015-05-15 13:55:05.714923 [DEBUG] switch_core_media.c:5147 AUDIO RTP [sofia/internal/1004] YYY.YYY.YYY.YYY port 20610 -> 192.168.51.31 port 5000 codec: 8 ms: 20
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:3562 Starting timer [soft] 160 bytes per 20ms
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: START SESSION INITIALIZATION. sID=5.
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: ZID=346661636436616664366363.
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Loading User's profile:
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: allowclear: OFF
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: autosecure: ON
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: disclose_bit: OFF
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: signal. role: Initiator
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: TTL: 4294967295
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: SAS schemes:
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 B256
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 B32
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Ciphers:
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 AES3
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 AES1
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: PK schemes:
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 EC25
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 DH3k
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 DH2k
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 Mult
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: ATL:
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 HS32
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Hashes:
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 S256
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Session initialization - DONE. sID=5.2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: ATTACH NEW STREAM to sID=5:
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>.
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Empty slot was found - initializing new stream with ID=5.
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: Preparing ZRTP Hello according to the Session profile.
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp main]: ATTACH NEW STREAM - DONE.
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: START STREAM ID=5 mode=CLEAR state=ACTIVE.
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=5 CLEAR switching <ACTIVE> ---> <START>.
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <HELLO> ssrc=559348913 seq=37145 size=144. Stream 5:CLEAR:START
2015-05-15 13:55:05.714923 [DEBUG] switch_channel.c:3635 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:55:05.714923 [NOTICE] sofia.c:7484 Channel [sofia/internal/1004] has been answered
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp mitm]: RESOLVE MITM CALL s1=5, s2=4...
2015-05-15 13:55:05.714923 [DEBUG] switch_rtp.c:1370 [ zrtp mitm]: RESOLVE MITM CALL s1=5, s2=4...
2015-05-15 13:55:05.714923 [DEBUG] switch_core_codec.c:246 sofia/internal/1001 at sip.domain.com Restore previous codec PCMA:8.
2015-05-15 13:55:05.714923 [DEBUG] switch_channel.c:3689 (sofia/internal/1004) Callstate Change RINGING -> ACTIVE
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:55:05.714923 [DEBUG] mod_sofia.c:780 Local SDP sofia/internal/1001 at sip.domain.com:
v=0
o=FreeSWITCH 1431670383 1431670385 IN IP4 YYY.YYY.YYY.YYY
s=FreeSWITCH
c=IN IP4 YYY.YYY.YYY.YYY
t=0 0
m=audio 20514 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
a=rtcp:20515 IN IP4 YYY.YYY.YYY.YYY nua.c:879 nua_respond() nua: nua_respond: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
nua_stack.c:529 nua_signal() nua(0x7fccf0091540): sent signal r_respond
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf0091660, ...) called
2015-05-15 13:55:05.714923 [DEBUG] switch_core_session.c:912 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fccf0091660, (nil), 0x7fcd3000f130, -1) called
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
2015-05-15 13:55:05.714923 [NOTICE] switch_ivr_originate.c:3519 Channel [sofia/internal/1001 at sip.domain.com] has been answered
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fccf0091660, [(nil)], [0x7fcd0bdfcc38], [0x7fcd0bdfcc34]) called
tport.c:3257 tport_tsend() tport_tsend(0x7fccf00a2eb0) tpn = TLS/XXX.XXX.XXX.XXX:15193
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf00b5420 883 (883)
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf008e3e0 260 (260)
tport.c:3492 tport_send_msg() tport_vsend returned 1143
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nta.c:6791 incoming_reply() nta: sent 200 OK for INVITE (28199)
nta.c:1348 set_timeout() nta: timer shortened to 500 ms
nua_session.c:4139 signal_call_state_change() nua(0x7fccf0091540): call state changed: early -> completed, sent answer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fccf0091660, [0x7fcd0bdfcce8], [0x7fcd0bdfccf0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7fccf0091660, ...) called
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:55:05.714923 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:55:05.714923 [DEBUG] switch_channel.c:3689 (sofia/internal/1001 at sip.domain.com) Callstate Change EARLY -> ACTIVE
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:55:05.714923 [DEBUG] sofia.c:6623 Channel sofia/internal/1001 at sip.domain.com entering state [completed][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:55:05.714923 [DEBUG] switch_ivr_originate.c:3577 Originate Resulted in Success: [sofia/internal/1004]
2015-05-15 13:55:05.714923 [DEBUG] switch_core_session.c:912 Send signal sofia/internal/1004 [BREAK]
2015-05-15 13:55:05.714923 [DEBUG] switch_core_session.c:912 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:55:05.714923 [DEBUG] switch_ivr_bridge.c:1465 (sofia/internal/1004) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2015-05-15 13:55:05.714923 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1004 [BREAK]
2015-05-15 13:55:05.714923 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004) Running State Change CS_EXCHANGE_MEDIA
2015-05-15 13:55:05.714923 [DEBUG] switch_core_state_machine.c:538 (sofia/internal/1004) State EXCHANGE_MEDIA
2015-05-15 13:55:05.714923 [DEBUG] mod_sofia.c:594 SOFIA EXCHANGE_MEDIA
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf00a2eb0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf00a2eb0)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf00a2eb0): tls_read() returned 414
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf00a2eb0) msg 0x7fccf0092fb0 from (tls/XXX.XXX.XXX.XXX:15193) has 414 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7fccf00a2eb0): msg 0x7fccf0092fb0 (414 bytes) from tls/XXX.XXX.XXX.XXX:15193/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received BYE sip:1004 at YYY.YYY.YYY.YYY:9061;transport=tls SIP/2.0 (CSeq 28200)
nta.c:3174 agent_check_request_via() nta: Via check: received=XXX.XXX.XXX.XXX
nta.c:3060 agent_recv_request() nta: BYE (28200) going to existing leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-05-15 13:55:05.754963 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:55:05.754963 [DEBUG] switch_rtp.c:1370 [ zrtp utils]: Send <HELLO> ssrc=559348913 seq=37146 size=144. Stream 5:CLEAR:START
2015-05-15 13:55:05.794920 [DEBUG] switch_rtp.c:1370 [ zrtp mitm]: RESOLVE MITM CALL s1=5, s2=4...
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-05-15 13:55:05.794920 [NOTICE] sofia.c:952 Hangup sofia/internal/1001 at sip.domain.com [CS_EXECUTE] [NORMAL_CLEARING]
2015-05-15 13:55:05.794920 [DEBUG] switch_channel.c:3222 Send signal sofia/internal/1001 at sip.domain.com [KILL]
2015-05-15 13:55:05.794920 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7fccf0091540): sent signal r_respond
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7fccf0091540): sent signal r_destroy
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf0091660, ...) called
tport.c:3257 tport_tsend() tport_tsend(0x7fccf00a2eb0) tpn = TLS/XXX.XXX.XXX.XXX:15193
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf00b8f60 539 (539)
tport.c:3492 tport_send_msg() tport_vsend returned 539
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (28200)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fccf0091540): removing session usage
nua_session.c:4139 signal_call_state_change() nua(0x7fccf0091540): call state changed: completed -> terminated
soa.c:356 soa_destroy() soa_destroy(static::0x7fccf0091660) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fccf0093530)
nta.c:5744 incoming_free() nta: incoming_free(0x7fccf00b6550)
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
2015-05-15 13:55:05.794920 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/internal/1001 at sip.domain.com]
2015-05-15 13:55:05.794920 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/1004 [BREAK]
2015-05-15 13:55:05.814915 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/internal/1004]
2015-05-15 13:55:05.814915 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:55:05.814915 [NOTICE] switch_ivr_bridge.c:754 Hangup sofia/internal/1004 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2015-05-15 13:55:05.814915 [DEBUG] switch_channel.c:3222 Send signal sofia/internal/1004 [KILL]
2015-05-15 13:55:05.814915 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1004 [BREAK]
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:538 (sofia/internal/1004) State EXCHANGE_MEDIA going to sleep
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004) Running State Change CS_HANGUP
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1004) Callstate Change ACTIVE -> HANGUP
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1004) State HANGUP
2015-05-15 13:55:05.814915 [DEBUG] switch_ivr_bridge.c:1563 sofia/internal/1004 skip receive message [UNBRIDGE] (channel is comngup already)
2015-05-15 13:55:05.814915 [DEBUG] switch_ivr_bridge.c:1566 sofia/internal/1001 at sip.domain.com skip receive message [UNBRIDGE] (channel is comngup already)
2015-05-15 13:55:05.814915 [DEBUG] mod_sofia.c:407 sofia/internal/1004 Overriding SIP cause 480 with 200 from the other leg
2015-05-15 13:55:05.814915 [DEBUG] mod_sofia.c:413 Channel sofia/internal/1004 hanging up, cause: NORMAL_CLEARING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_session.c:2901 sofia/internal/1001 at sip.domain.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is comngup already)
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/1001 at sip.domain.com) State EXECUTE going to sleep
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001 at sip.domain.com) Running State Change CS_HANGUP
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1001 at sip.domain.com) Callstate Change ACTIVE -> HANGUP
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1001 at sip.domain.com) State HANGUP
2015-05-15 13:55:05.814915 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/internal/1004
2015-05-15 13:55:05.814915 [DEBUG] mod_sofia.c:413 Channel sofia/internal/1001 at sip.domain.com hanging up, cause: NORMAL_CLEARING
nua.c:645 nua_bye() nua: nua_bye: entering
nua_stack.c:529 nua_signal() nua(0x7fcccc00a070): sent signal r_bye
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1004 Standard HANGUP, cause: NORMAL_CLEARING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1004) State HANGUP going to sleep
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7fccf008b650, ...) called
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/1004) State Change CS_HANGUP -> CS_REPORTING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1004 [BREAK]
soa.c:1784 soa_terminate() soa_terminate(static::0x7fccf008b650) called
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fccf008b650) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:4588 tport_by_name() tport(0x7fccf0004620): found 0x7fccf0077460 by name tls/XXX.XXX.XXX.XXX:15194
tport.c:3257 tport_tsend() tport_tsend(0x7fccf0077460) tpn = tls/XXX.XXX.XXX.XXX:15194
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004) Running State Change CS_REPORTING
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0057610 0x7fccf008e9c0 657 (657)
tport.c:3492 tport_send_msg() tport_vsend returned 657
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf0077460): reset timer
nta.c:8304 outgoing_send() nta: sent BYE (75509385) to tls/XXX.XXX.XXX.XXX:15194
tport.c:4160 tport_pend() tport_pend(0x7fccf0077460): pending 0x7fccf008b8c0 for tls/XXX.XXX.XXX.XXX:15194 (already 0)
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1004) State REPORTING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001 at sip.domain.com Standard HANGUP, cause: NORMAL_CLEARING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1001 at sip.domain.com) State HANGUP going to sleep
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/1001 at sip.domain.com) State Change CS_HANGUP -> CS_REPORTING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001 at sip.domain.com) Running State Change CS_REPORTING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1001 at sip.domain.com) State REPORTING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:104 sofia/internal/1004 Standard REPORTING, cause: NORMAL_CLEARING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1004) State REPORTING going to sleep
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:498 (sofia/internal/1004) State Change CS_REPORTING -> CS_DESTROY
2015-05-15 13:55:05.814915 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1004 [BREAK]
2015-05-15 13:55:05.814915 [DEBUG] switch_core_session.c:1623 Session 6 (sofia/internal/1004) Locked, Waiting on external entities
2015-05-15 13:55:05.814915 [NOTICE] switch_core_session.c:1641 Session 6 (sofia/internal/1004) Ended
2015-05-15 13:55:05.814915 [NOTICE] switch_core_session.c:1645 Close Channel sofia/internal/1004 [CS_DESTROY]
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:626 (sofia/internal/1004) Running State Change CS_DESTROY
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1004) State DESTROY
2015-05-15 13:55:05.814915 [DEBUG] mod_sofia.c:323 sofia/internal/1004 SOFIA DESTROY
2015-05-15 13:55:05.814915 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: STOP STREAM ID=5 mode=CLEAR state=START.
2015-05-15 13:55:05.814915 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <NONE>.
2015-05-15 13:55:05.814915 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE.
2015-05-15 13:55:05.814915 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE.
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:111 sofia/internal/1004 Standard DESTROY
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1004) State DESTROY going to sleep
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:104 sofia/internal/1001 at sip.domain.com Standard REPORTING, cause: NORMAL_CLEARING
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1001 at sip.domain.com) State REPORTING going to sleep
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:498 (sofia/internal/1001 at sip.domain.com) State Change CS_REPORTING -> CS_DESTROY
2015-05-15 13:55:05.814915 [DEBUG] switch_core_session.c:1396 Send signal sofia/internal/1001 at sip.domain.com [BREAK]
2015-05-15 13:55:05.814915 [DEBUG] switch_core_session.c:1623 Session 5 (sofia/internal/1001 at sip.domain.com) Locked, Waiting on external entities
2015-05-15 13:55:05.814915 [NOTICE] switch_core_session.c:1641 Session 5 (sofia/internal/1001 at sip.domain.com) Ended
2015-05-15 13:55:05.814915 [NOTICE] switch_core_session.c:1645 Close Channel sofia/internal/1001 at sip.domain.com [CS_DESTROY]
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:626 (sofia/internal/1001 at sip.domain.com) Running State Change CS_DESTROY
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1001 at sip.domain.com) State DESTROY
2015-05-15 13:55:05.814915 [DEBUG] mod_sofia.c:323 sofia/internal/1001 at sip.domain.com SOFIA DESTROY
2015-05-15 13:55:05.814915 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: STOP STREAM ID=4 mode=DH state=SECURE.
2015-05-15 13:55:05.814915 [DEBUG] switch_rtp.c:1370 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <NONE>.
2015-05-15 13:55:05.814915 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE.
2015-05-15 13:55:05.814915 [DEBUG] switch_rtp.c:1370 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE.
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:111 sofia/internal/1001 at sip.domain.com Standard DESTROY
2015-05-15 13:55:05.814915 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1001 at sip.domain.com) State DESTROY going to sleep
nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
tport.c:3257 tport_tsend() tport_tsend(0x7fccf00a2eb0) tpn = TLS/XXX.XXX.XXX.XXX:15193
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf00b5420 883 (883)
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fccf0079900 0x7fccf008e3e0 260 (260)
tport.c:3492 tport_send_msg() tport_vsend returned 1143
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free
nta.c:1296 agent_timer() nta: timer set next to 1000 ms
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf0077460): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf0077460)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf0077460): tls_read() returned 1
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf0077460) msg 0x7fccf00b6550 from (tls/XXX.XXX.XXX.XXX:15194) has 1 bytes, veclen = 1
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf0077460): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf0077460): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf0077460)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf0077460): tls_read() returned 489
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf0077460) msg 0x7fccf00b6550 from (tls/XXX.XXX.XXX.XXX:15194) has 489 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7fccf0077460): msg 0x7fccf00b6550 (490 bytes) from tls/XXX.XXX.XXX.XXX:15194/sips next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (75509385)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 505.558 ms
tport.c:4222 tport_release() tport_release(0x7fccf0077460): 0x7fccf008b8c0 by 0x7fccf00a1400 with 0x7fccf00b6550
nua_session.c:4139 signal_call_state_change() nua(0x7fcccc00a070): call state changed: terminating -> terminated
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fcccc00a070): removing session usage
soa.c:356 soa_destroy() soa_destroy(static::0x7fccf008b650) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fccf00b0bb0)
nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7fcccc00a070
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nta.c:8722 outgoing_free() nta: outgoing_free(0x7fccf00a1400)
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf0077460): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7fcccc00a070): sent signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
tport.c:2773 tport_wakeup() tport_wakeup(0x7fccf00a2eb0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fccf00a2eb0)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fccf00a2eb0): tls_read() returned 374
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fccf00a2eb0) msg 0x7fccf008b450 from (tls/XXX.XXX.XXX.XXX:15193) has 374 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7fccf00a2eb0): msg 0x7fccf008b450 (374 bytes) from tls/XXX.XXX.XXX.XXX:15193/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sip:1004 at YYY.YYY.YYY.YYY:9061;transport=tls SIP/2.0 (CSeq 28199)
nta.c:3174 agent_check_request_via() nta: Via check: received=XXX.XXX.XXX.XXX
nta.c:3019 agent_recv_request() nta: ACK (28199) is going to INVITE (28199)
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
tport.c:2296 tport_set_secondary_timer() tport(0x7fccf00a2eb0): reset timer
nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fcd0bdfcc60)
nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 0/0 term, 1/1 free
nta.c:1296 agent_timer() nta: timer set next to 30493 ms
Brian West <brian at freeswitch.org> írta:
>Its either you've enabled proxy media mode, or auto proxy due to the zrtp-hash in the sdp's hard to tell 100% but I suspect thats what is taking place.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150515/150ce0f9/attachment-0001.html
Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users
mailing list