[Freeswitch-users] FS not supporting ZRTP (MITM)

Sun Jul 21 22:20:29 MSD 2013

I've installed fresh FS ver-1.2.11 (latest stable) with --enable-zrtp.
The server is an Xeon 3Ghz Centos 5.3.
I've set vars.xml <X-PRE-PROCESS cmd="set" data="zrtp_secure_media=true"/>.
I use the default sip_profile internal.xml with ext 1001 and 1002.

Both proxy/bypass are commented and false (default setup).
Using default dialplan public&default.xml.

The problem is that I cannot get the MITM situation even with two simple
ZRTP clients.
(The MITM is required for end-2-site encryption when dialing through a SIP
provider).
The FS detects the SDP ZRTP but not generating back to back ZRTP sessions
between the endpoints.
I've reinstall FS with ZRTP twice and the problem is the same.
I can get end-2-end ZRTP with both proxy and bypass media modes.

I've install FS with ZRTP, with the same config xml files, on a remote EC2
and all works fine with MITM.

What else should I check to find out why FS does not activate the internal
ZRTP module?

Below is the log for call between 1001 and 1002 (with no ZRTP initiative).

2013-07-21 20:18:23.968057 [NOTICE] switch_channel.c:1030 New Channel
sofia/internal/1002 at domain.com [2ac8892b-16ee-419f-8369-942bee25ebeb]
2013-07-21 20:18:23.968057 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:23.968057 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:23.968057 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/1002 at domain.com) Running State Change CS_NEW
2013-07-21 20:18:23.968057 [DEBUG] switch_core_state_machine.c:433
(sofia/internal/1002 at domain.com) State NEW
2013-07-21 20:18:23.988080 [DEBUG] sofia.c:7888 IP 2.3.4.5 Rejected by acl
"domains". Falling back to Digest auth.
2013-07-21 20:18:23.988080 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:23.988080 [DEBUG] sofia.c:1767 detaching session
2ac8892b-16ee-419f-8369-942bee25ebeb
2013-07-21 20:18:24.108098 [DEBUG] sofia.c:1859 Re-attaching to session
2ac8892b-16ee-419f-8369-942bee25ebeb
2013-07-21 20:18:24.108098 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:24.108098 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:24.108098 [DEBUG] sofia.c:7888 IP 2.3.4.5 Rejected by acl
"domains". Falling back to Digest auth.
2013-07-21 20:18:24.128130 [DEBUG] sofia.c:8874 Setting NAT mode based on
nat.auto
2013-07-21 20:18:24.128130 [DEBUG] sofia.c:5720 Channel
sofia/internal/1002 at domain.com entering state [received][100]
2013-07-21 20:18:24.128130 [DEBUG] sofia.c:5733 Remote SDP:
2013-07-21 20:18:24.128130 [DEBUG] sofia_glue.c:4072 Found audio zrtp-hash;
setting r_sdp_audio_zrtp_hash=1.10
63cad5b5a616388ca2578dde581b676c4ecacb7c754fc7716f07dbf249746af5
2013-07-21 20:18:24.128130 [DEBUG] sofia.c:5947
(sofia/internal/1002 at domain.com) State Change CS_NEW -> CS_INIT
2013-07-21 20:18:24.128130 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:24.128130 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/1002 at domain.com) Running State Change CS_INIT
2013-07-21 20:18:24.128130 [DEBUG] switch_core_state_machine.c:454
(sofia/internal/1002 at domain.com) State INIT
2013-07-21 20:18:24.128130 [DEBUG] mod_sofia.c:87
sofia/internal/1002 at domain.com SOFIA INIT
2013-07-21 20:18:24.128130 [DEBUG] mod_sofia.c:127
(sofia/internal/1002 at domain.com) State Change CS_INIT -> CS_ROUTING
2013-07-21 20:18:24.128130 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:24.128130 [DEBUG] switch_core_state_machine.c:454
(sofia/internal/1002 at domain.com) State INIT going to sleep
2013-07-21 20:18:24.128130 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/1002 at domain.com) Running State Change CS_ROUTING
2013-07-21 20:18:24.128130 [DEBUG] switch_channel.c:2111
(sofia/internal/1002 at domain.com) Callstate Change DOWN -> RINGING
2013-07-21 20:18:24.128130 [DEBUG] switch_core_state_machine.c:470
(sofia/internal/1002 at domain.com) State ROUTING
2013-07-21 20:18:24.128130 [DEBUG] mod_sofia.c:150
sofia/internal/1002 at domain.com SOFIA ROUTING
2013-07-21 20:18:24.128130 [DEBUG] switch_core_state_machine.c:117
sofia/internal/1002 at domain.com Standard ROUTING
2013-07-21 20:18:24.128130 [INFO] mod_dialplan_xml.c:558 Processing 1002
<1002>->1001 in context default
2013-07-21 20:18:24.148132 [DEBUG] switch_core_state_machine.c:167
(sofia/internal/1002 at domain.com) State Change CS_ROUTING -> CS_EXECUTE
2013-07-21 20:18:24.148132 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:24.148132 [DEBUG] switch_core_state_machine.c:470
(sofia/internal/1002 at domain.com) State ROUTING going to sleep
2013-07-21 20:18:24.148132 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/1002 at domain.com) Running State Change CS_EXECUTE
2013-07-21 20:18:24.148132 [DEBUG] switch_core_state_machine.c:477
(sofia/internal/1002 at domain.com) State EXECUTE
2013-07-21 20:18:24.148132 [DEBUG] mod_sofia.c:243
sofia/internal/1002 at domain.com SOFIA EXECUTE
2013-07-21 20:18:24.148132 [DEBUG] switch_core_state_machine.c:209
sofia/internal/1002 at domain.com Standard EXECUTE
2013-07-21 20:18:24.148132 [DEBUG] switch_channel.c:1222 EXPORT
(export_vars) [RFC2822_DATE]=[Sun, 21 Jul 2013 20:18:24 +0300]
2013-07-21 20:18:24.148132 [DEBUG] switch_channel.c:1222 EXPORT
(export_vars) [dialed_extension]=[1001]
2013-07-21 20:18:24.148132 [INFO] switch_ivr_async.c:3692 Bound B-Leg: *1
execute_extension::dx XML features
2013-07-21 20:18:24.148132 [INFO] switch_ivr_async.c:3692 Bound B-Leg: *2
record_session::/usr/local/freeswitch/recordings/1002.2013-07-21-20-18-24.wav
2013-07-21 20:18:24.148132 [INFO] switch_ivr_async.c:3692 Bound B-Leg: *3
execute_extension::cf XML features
2013-07-21 20:18:24.148132 [INFO] switch_ivr_async.c:3692 Bound B-Leg: *4
execute_extension::att_xfer XML features
2013-07-21 20:18:24.148132 [DEBUG] mod_dptools.c:1376
sofia/internal/1002 at domain.com SET [ringback]=[%(2000,4000,440,480)]
2013-07-21 20:18:24.148132 [DEBUG] mod_dptools.c:1376
sofia/internal/1002 at domain.com SET [transfer_ringback]=[local_stream://moh]
2013-07-21 20:18:24.148132 [DEBUG] mod_dptools.c:1376
sofia/internal/1002 at domain.com SET [call_timeout]=[30]
2013-07-21 20:18:24.148132 [DEBUG] mod_dptools.c:1376
sofia/internal/1002 at domain.com SET [hangup_after_bridge]=[true]
2013-07-21 20:18:24.148132 [DEBUG] mod_dptools.c:1376
sofia/internal/1002 at domain.com SET [continue_on_fail]=[true]
2013-07-21 20:18:24.168166 [DEBUG] mod_dptools.c:1376
sofia/internal/1002 at domain.com SET [called_party_callgroup]=[techsupport]
2013-07-21 20:18:24.168166 [DEBUG] switch_channel.c:1176
sofia/internal/1002 at domain.com EXPORTING[export_vars] [RFC2822_DATE]=[Sun,
21 Jul 2013 20:18:24 +0300] to event
2013-07-21 20:18:24.168166 [DEBUG] switch_channel.c:1176
sofia/internal/1002 at domain.com EXPORTING[export_vars]
[dialed_extension]=[1001] to event
2013-07-21 20:18:24.168166 [DEBUG] switch_ivr_originate.c:2060 Parsing
global variables
2013-07-21 20:18:24.188169 [DEBUG] switch_channel.c:1176
sofia/internal/1002 at domain.com EXPORTING[export_vars] [RFC2822_DATE]=[Sun,
21 Jul 2013 20:18:24 +0300] to event
2013-07-21 20:18:24.188169 [DEBUG] switch_channel.c:1176
sofia/internal/1002 at domain.com EXPORTING[export_vars]
[dialed_extension]=[1001] to event
2013-07-21 20:18:24.188169 [DEBUG] switch_ivr_originate.c:2060 Parsing
global variables
2013-07-21 20:18:24.188169 [DEBUG] switch_event.c:1617 Parsing variable
[sip_invite_domain]=[domain1001.com]
2013-07-21 20:18:24.188169 [DEBUG] switch_event.c:1617 Parsing variable
[presence_id]=[1001 at domain1001.com]
2013-07-21 20:18:24.188169 [NOTICE] switch_channel.c:1030 New Channel
sofia/internal/sip:1001 at 192.168.1.100:51783
[cdf668f4-5a41-4703-9a22-d40299ce6c82]
2013-07-21 20:18:24.188169 [DEBUG] mod_sofia.c:5189
(sofia/internal/sip:1001 at 192.168.1.100:51783) State Change CS_NEW -> CS_INIT
2013-07-21 20:18:24.188169 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:24.188169 [DEBUG] sofia_glue.c:4015 Passing a-leg remote
zrtp-hash (audio) to b-leg
2013-07-21 20:18:24.188169 [DEBUG] mod_sofia.c:5259 [zrtp_passthru] Setting
a-leg inherit_codec=true
2013-07-21 20:18:24.188169 [DEBUG] mod_sofia.c:5262 [zrtp_passthru] Setting
b-leg
absolute_codec_string='SILK at 8000h@20i,GSM at 8000h@20i at 13200b,PCMU at 8000h@20i at 64000b'
2013-07-21 20:18:24.188169 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/sip:1001 at 192.168.1.100:51783) Running State Change CS_INIT
2013-07-21 20:18:24.188169 [DEBUG] switch_core_state_machine.c:454
(sofia/internal/sip:1001 at 192.168.1.100:51783) State INIT
2013-07-21 20:18:24.188169 [DEBUG] mod_sofia.c:87
sofia/internal/sip:1001 at 192.168.1.100:51783 SOFIA INIT
2013-07-21 20:18:24.188169 [DEBUG] sofia_glue.c:349 Adding audio
a=zrtp-hash:1.10
63cad5b5a616388ca2578dde581b676c4ecacb7c754fc7716f07dbf249746af5
2013-07-21 20:18:24.188169 [DEBUG] sofia_glue.c:2649
sip:1001 at 109.160.136.237:57182;transport=TCP Setting proxy route to
sofia/internal/sip:1001 at 192.168.1.100:51783
2013-07-21 20:18:24.188169 [DEBUG] sofia_glue.c:2678 Local SDP:
2013-07-21 20:18:24.188169 [DEBUG] mod_sofia.c:127
(sofia/internal/sip:1001 at 192.168.1.100:51783) State Change CS_INIT ->
CS_ROUTING
2013-07-21 20:18:24.188169 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:24.188169 [DEBUG] switch_core_state_machine.c:454
(sofia/internal/sip:1001 at 192.168.1.100:51783) State INIT going to sleep
2013-07-21 20:18:24.188169 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/sip:1001 at 192.168.1.100:51783) Running State Change
CS_ROUTING
2013-07-21 20:18:24.188169 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:24.188169 [DEBUG] switch_core_state_machine.c:470
(sofia/internal/sip:1001 at 192.168.1.100:51783) State ROUTING
2013-07-21 20:18:24.188169 [DEBUG] mod_sofia.c:150
sofia/internal/sip:1001 at 192.168.1.100:51783 SOFIA ROUTING
2013-07-21 20:18:24.188169 [DEBUG] switch_ivr_originate.c:67
(sofia/internal/sip:1001 at 192.168.1.100:51783) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2013-07-21 20:18:24.188169 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:24.188169 [DEBUG] switch_core_state_machine.c:470
(sofia/internal/sip:1001 at 192.168.1.100:51783) State ROUTING going to sleep
2013-07-21 20:18:24.188169 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/sip:1001 at 192.168.1.100:51783) Running State Change
CS_CONSUME_MEDIA
2013-07-21 20:18:24.188169 [DEBUG] switch_core_state_machine.c:489
(sofia/internal/sip:1001 at 192.168.1.100:51783) State CONSUME_MEDIA
2013-07-21 20:18:24.188169 [DEBUG] switch_core_state_machine.c:489
(sofia/internal/sip:1001 at 192.168.1.100:51783) State CONSUME_MEDIA going to
sleep
2013-07-21 20:18:24.188169 [DEBUG] sofia.c:5720 Channel
sofia/internal/sip:1001 at 192.168.1.100:51783 entering state [calling][0]
2013-07-21 20:18:24.381616 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:24.381616 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:24.381616 [DEBUG] sofia.c:5720 Channel
sofia/internal/sip:1001 at 192.168.1.100:51783 entering state [proceeding][180]
2013-07-21 20:18:24.381616 [NOTICE] sofia.c:5815 Ring-Ready
sofia/internal/sip:1001 at 192.168.1.100:51783!
2013-07-21 20:18:24.381616 [DEBUG] switch_channel.c:3175
(sofia/internal/sip:1001 at 192.168.1.100:51783) Callstate Change DOWN ->
RINGING
2013-07-21 20:18:24.401623 [INFO] switch_ivr_originate.c:1190 Sending early
media
2013-07-21 20:18:24.401623 [DEBUG] sofia_glue.c:4072 Found audio zrtp-hash;
setting r_sdp_audio_zrtp_hash=1.10
63cad5b5a616388ca2578dde581b676c4ecacb7c754fc7716f07dbf249746af5
2013-07-21 20:18:24.401623 [DEBUG] sofia_glue.c:4015 Passing a-leg remote
zrtp-hash (audio) to b-leg
2013-07-21 20:18:24.401623 [DEBUG] sofia_glue.c:5181 Audio Codec Compare
[SILK:96:8000:20:0]/[SILK:117:8000:20:20000]
2013-07-21 20:18:24.401623 [DEBUG] sofia_glue.c:3124 Set Codec
sofia/internal/1002 at domain.com SILK/8000 20 ms 160 samples 20000 bits
2013-07-21 20:18:24.401623 [DEBUG] switch_core_codec.c:111
sofia/internal/1002 at domain.com Original read codec set to SILK:117
2013-07-21 20:18:24.401623 [DEBUG] sofia_glue.c:5312 Set 2833 dtmf send/recv
payload to 101
2013-07-21 20:18:24.401623 [DEBUG] sofia_glue.c:3383 AUDIO RTP
[sofia/internal/1002 at domain.com] 91.205.155.18 port 19562 -> 10.195.42.107
port 4006 codec: 96 ms: 20
2013-07-21 20:18:24.401623 [DEBUG] switch_rtp.c:1985 Starting timer [soft]
160 bytes per 20ms
2013-07-21 20:18:24.401623 [DEBUG] sofia_glue.c:3647 Set 2833 dtmf send
payload to 101
2013-07-21 20:18:24.401623 [DEBUG] sofia_glue.c:3653 Set 2833 dtmf receive
payload to 101
2013-07-21 20:18:24.401623 [DEBUG] sofia_glue.c:3680
sofia/internal/1002 at domain.com Set rtp dtmf delay to 40
2013-07-21 20:18:24.401623 [INFO] switch_channel.c:3217
sofia/internal/1002 at domain.com ZRTP not negotiated on both sides; disabling
ZRTP passthru mode.
2013-07-21 20:18:24.401623 [NOTICE] sofia_glue.c:4291 Pre-Answer
sofia/internal/1002 at domain.com!
2013-07-21 20:18:24.401623 [DEBUG] switch_channel.c:3299
(sofia/internal/1002 at domain.com) Callstate Change RINGING -> EARLY
2013-07-21 20:18:24.401623 [DEBUG] mod_sofia.c:2847 Ring SDP:
2013-07-21 20:18:24.401623 [DEBUG] switch_core_session.c:854 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:24.401623 [DEBUG] switch_ivr_originate.c:1247 Raw Codec
Activation Success L16 at 8000hz 1 channel 20ms
2013-07-21 20:18:24.401623 [DEBUG] switch_core_codec.c:219
sofia/internal/1002 at domain.com Push codec L16:70
2013-07-21 20:18:24.401623 [DEBUG] switch_ivr_originate.c:1315 Play Ringback
Tone [%(2000,4000,440,480)]
2013-07-21 20:18:24.401623 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:24.441618 [DEBUG] sofia.c:5720 Channel
sofia/internal/1002 at domain.com entering state [early][183]
2013-07-21 20:18:24.801608 [INFO] switch_rtp.c:3687 Auto Changing port from
10.195.42.107:4006 to 2.3.4.5:26681
2013-07-21 20:18:30.561547 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:30.561547 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:30.561547 [DEBUG] sofia.c:5720 Channel
sofia/internal/sip:1001 at 192.168.1.100:51783 entering state [completing][200]
2013-07-21 20:18:30.561547 [DEBUG] sofia.c:5733 Remote SDP:
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:4072 Found audio zrtp-hash;
setting r_sdp_audio_zrtp_hash=1.10
788348c399ae6170adaee70b74ea3d584c8db158d41c3a650faedaa8a1ce67df
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:4015 Passing a-leg remote
zrtp-hash (audio) to b-leg
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:4025 Passing b-leg remote
zrtp-hash (audio) to a-leg
2013-07-21 20:18:30.561547 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:30.561547 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:30.561547 [DEBUG] sofia.c:5720 Channel
sofia/internal/sip:1001 at 192.168.1.100:51783 entering state [ready][200]
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:4072 Found audio zrtp-hash;
setting r_sdp_audio_zrtp_hash=1.10
788348c399ae6170adaee70b74ea3d584c8db158d41c3a650faedaa8a1ce67df
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:4015 Passing a-leg remote
zrtp-hash (audio) to b-leg
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:4025 Passing b-leg remote
zrtp-hash (audio) to a-leg
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:5181 Audio Codec Compare
[SILK:98:8000:20:0]/[SILK:117:8000:20:20000]
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:3124 Set Codec
sofia/internal/sip:1001 at 192.168.1.100:51783 SILK/8000 20 ms 160 samples
20000 bits
2013-07-21 20:18:30.561547 [DEBUG] switch_core_codec.c:111
sofia/internal/sip:1001 at 192.168.1.100:51783 Original read codec set to
SILK:117
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:5303 Set 2833 dtmf send
payload to 101
2013-07-21 20:18:30.561547 [INFO] switch_channel.c:3217
sofia/internal/sip:1001 at 192.168.1.100:51783 ZRTP not negotiated on both
sides; disabling ZRTP passthru mode.
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:3383 AUDIO RTP
[sofia/internal/sip:1001 at 192.168.1.100:51783] 91.205.155.18 port 19240 ->
109.160.136.237 port 4006 codec: 98 ms: 20
2013-07-21 20:18:30.561547 [DEBUG] switch_rtp.c:1985 Starting timer [soft]
160 bytes per 20ms
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:3647 Set 2833 dtmf send
payload to 101
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:3653 Set 2833 dtmf receive
payload to 101
2013-07-21 20:18:30.561547 [DEBUG] sofia_glue.c:3680
sofia/internal/sip:1001 at 192.168.1.100:51783 Set rtp dtmf delay to 40
2013-07-21 20:18:30.561547 [DEBUG] switch_channel.c:3530 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:30.561547 [NOTICE] sofia.c:6476 Channel
[sofia/internal/sip:1001 at 192.168.1.100:51783] has been answered
2013-07-21 20:18:30.561547 [DEBUG] switch_channel.c:3576
(sofia/internal/sip:1001 at 192.168.1.100:51783) Callstate Change RINGING ->
ACTIVE
2013-07-21 20:18:30.581577 [DEBUG] switch_core_codec.c:244
sofia/internal/1002 at domain.com Restore previous codec SILK:117.
2013-07-21 20:18:30.581577 [DEBUG] sofia_glue.c:564 Adding audio
a=zrtp-hash:1.10
788348c399ae6170adaee70b74ea3d584c8db158d41c3a650faedaa8a1ce67df
2013-07-21 20:18:30.581577 [DEBUG] mod_sofia.c:864 Local SDP
sofia/internal/1002 at domain.com:
2013-07-21 20:18:30.581577 [DEBUG] switch_core_session.c:854 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:30.581577 [NOTICE] switch_ivr_originate.c:3437 Channel
[sofia/internal/1002 at domain.com] has been answered
2013-07-21 20:18:30.581577 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:30.581577 [DEBUG] switch_channel.c:3576
(sofia/internal/1002 at domain.com) Callstate Change EARLY -> ACTIVE
2013-07-21 20:18:30.581577 [DEBUG] sofia.c:5720 Channel
sofia/internal/1002 at domain.com entering state [completed][200]
2013-07-21 20:18:30.581577 [DEBUG] switch_ivr_originate.c:3494 Originate
Resulted in Success: [sofia/internal/sip:1001 at 192.168.1.100:51783]
2013-07-21 20:18:30.581577 [DEBUG] switch_ivr_originate.c:3494 Originate
Resulted in Success: [sofia/internal/sip:1001 at 192.168.1.100:51783]
2013-07-21 20:18:30.581577 [DEBUG] switch_core_session.c:854 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:30.581577 [DEBUG] switch_core_session.c:854 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:30.581577 [DEBUG] switch_ivr_bridge.c:1423
(sofia/internal/sip:1001 at 192.168.1.100:51783) State Change CS_CONSUME_MEDIA
-> CS_EXCHANGE_MEDIA
2013-07-21 20:18:30.581577 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:30.581577 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/sip:1001 at 192.168.1.100:51783) Running State Change
CS_EXCHANGE_MEDIA
2013-07-21 20:18:30.581577 [DEBUG] switch_core_state_machine.c:480
(sofia/internal/sip:1001 at 192.168.1.100:51783) State EXCHANGE_MEDIA
2013-07-21 20:18:30.581577 [DEBUG] mod_sofia.c:686 SOFIA EXCHANGE_MEDIA
2013-07-21 20:18:30.609131 [DEBUG] switch_rtp.c:3706 Correct ip/port
confirmed.
2013-07-21 20:18:30.681545 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:30.681545 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:30.681545 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:30.701558 [DEBUG] sofia.c:5720 Channel
sofia/internal/1002 at domain.com entering state [ready][200]
2013-07-21 20:18:30.701558 [DEBUG] switch_core_session.c:916 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:30.701558 [DEBUG] switch_core_session.c:916 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:38.644911 [DEBUG] switch_core_session.c:999 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:38.664923 [NOTICE] sofia.c:716 Hangup
sofia/internal/1002 at domain.com [CS_EXECUTE] [NORMAL_CLEARING]
2013-07-21 20:18:38.664923 [DEBUG] switch_channel.c:3130 Send signal
sofia/internal/1002 at domain.com [KILL]
2013-07-21 20:18:38.664923 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:38.664923 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD
DONE [sofia/internal/1002 at domain.com]
2013-07-21 20:18:38.664923 [DEBUG] switch_ivr_bridge.c:658 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:38.664923 [DEBUG] switch_ivr_bridge.c:557
sofia/internal/1002 at domain.com ending bridge by request from write function
2013-07-21 20:18:38.664923 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD
DONE [sofia/internal/sip:1001 at 192.168.1.100:51783]
2013-07-21 20:18:38.664923 [DEBUG] switch_ivr_bridge.c:658 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:38.664923 [NOTICE] switch_ivr_bridge.c:721 Hangup
sofia/internal/sip:1001 at 192.168.1.100:51783 [CS_EXCHANGE_MEDIA]
[NORMAL_CLEARING]
2013-07-21 20:18:38.664923 [DEBUG] switch_channel.c:3130 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [KILL]
2013-07-21 20:18:38.664923 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:480
(sofia/internal/sip:1001 at 192.168.1.100:51783) State EXCHANGE_MEDIA going to
sleep
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/sip:1001 at 192.168.1.100:51783) Running State Change CS_HANGUP
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:678
(sofia/internal/sip:1001 at 192.168.1.100:51783) State HANGUP
2013-07-21 20:18:38.664923 [DEBUG] mod_sofia.c:498
sofia/internal/sip:1001 at 192.168.1.100:51783 Overriding SIP cause 480 with
200 from the other leg
2013-07-21 20:18:38.664923 [DEBUG] mod_sofia.c:504 Channel
sofia/internal/sip:1001 at 192.168.1.100:51783 hanging up, cause:
NORMAL_CLEARING
2013-07-21 20:18:38.664923 [DEBUG] mod_sofia.c:556 Sending BYE to
sofia/internal/sip:1001 at 192.168.1.100:51783
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:48
sofia/internal/sip:1001 at 192.168.1.100:51783 Standard HANGUP, cause:
NORMAL_CLEARING
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:678
(sofia/internal/sip:1001 at 192.168.1.100:51783) State HANGUP going to sleep
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:689
(sofia/internal/sip:1001 at 192.168.1.100:51783) Callstate Change ACTIVE ->
HANGUP
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:446
(sofia/internal/sip:1001 at 192.168.1.100:51783) State Change CS_HANGUP ->
CS_REPORTING
2013-07-21 20:18:38.664923 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/sip:1001 at 192.168.1.100:51783) Running State Change
CS_REPORTING
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:761
(sofia/internal/sip:1001 at 192.168.1.100:51783) State REPORTING
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:92
sofia/internal/sip:1001 at 192.168.1.100:51783 Standard REPORTING, cause:
NORMAL_CLEARING
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:761
(sofia/internal/sip:1001 at 192.168.1.100:51783) State REPORTING going to sleep
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:440
(sofia/internal/sip:1001 at 192.168.1.100:51783) State Change CS_REPORTING ->
CS_DESTROY
2013-07-21 20:18:38.664923 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/sip:1001 at 192.168.1.100:51783 [BREAK]
2013-07-21 20:18:38.664923 [DEBUG] switch_core_session.c:1542 Session 45
(sofia/internal/sip:1001 at 192.168.1.100:51783) Locked, Waiting on external
entities
2013-07-21 20:18:38.664923 [DEBUG] switch_ivr_bridge.c:1524
sofia/internal/1002 at domain.com skip receive message [UNBRIDGE] (channel is
hungup already)
2013-07-21 20:18:38.664923 [DEBUG] switch_core_session.c:2740
sofia/internal/1002 at domain.com skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:477
(sofia/internal/1002 at domain.com) State EXECUTE going to sleep
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/1002 at domain.com) Running State Change CS_HANGUP
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:678
(sofia/internal/1002 at domain.com) State HANGUP
2013-07-21 20:18:38.664923 [DEBUG] mod_sofia.c:504 Channel
sofia/internal/1002 at domain.com hanging up, cause: NORMAL_CLEARING
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:48
sofia/internal/1002 at domain.com Standard HANGUP, cause: NORMAL_CLEARING
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:678
(sofia/internal/1002 at domain.com) State HANGUP going to sleep
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:689
(sofia/internal/1002 at domain.com) Callstate Change ACTIVE -> HANGUP
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:446
(sofia/internal/1002 at domain.com) State Change CS_HANGUP -> CS_REPORTING
2013-07-21 20:18:38.664923 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/1002 at domain.com) Running State Change CS_REPORTING
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:761
(sofia/internal/1002 at domain.com) State REPORTING
2013-07-21 20:18:38.664923 [NOTICE] switch_core_session.c:1560 Session 45
(sofia/internal/sip:1001 at 192.168.1.100:51783) Ended
2013-07-21 20:18:38.664923 [NOTICE] switch_core_session.c:1564 Close Channel
sofia/internal/sip:1001 at 192.168.1.100:51783 [CS_DESTROY]
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:565
(sofia/internal/sip:1001 at 192.168.1.100:51783) Callstate Change HANGUP ->
DOWN
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:568
(sofia/internal/sip:1001 at 192.168.1.100:51783) Running State Change
CS_DESTROY
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:578
(sofia/internal/sip:1001 at 192.168.1.100:51783) State DESTROY
2013-07-21 20:18:38.664923 [DEBUG] mod_sofia.c:397
sofia/internal/sip:1001 at 192.168.1.100:51783 SOFIA DESTROY
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:99
sofia/internal/sip:1001 at 192.168.1.100:51783 Standard DESTROY
2013-07-21 20:18:38.664923 [DEBUG] switch_core_state_machine.c:578
(sofia/internal/sip:1001 at 192.168.1.100:51783) State DESTROY going to sleep
2013-07-21 20:18:38.721464 [DEBUG] switch_core_state_machine.c:92
sofia/internal/1002 at domain.com Standard REPORTING, cause: NORMAL_CLEARING
2013-07-21 20:18:38.721464 [DEBUG] switch_core_state_machine.c:761
(sofia/internal/1002 at domain.com) State REPORTING going to sleep
2013-07-21 20:18:38.721464 [DEBUG] switch_core_state_machine.c:440
(sofia/internal/1002 at domain.com) State Change CS_REPORTING -> CS_DESTROY
2013-07-21 20:18:38.721464 [DEBUG] switch_core_session.c:1334 Send signal
sofia/internal/1002 at domain.com [BREAK]
2013-07-21 20:18:38.721464 [DEBUG] switch_core_session.c:1542 Session 44
(sofia/internal/1002 at domain.com) Locked, Waiting on external entities
2013-07-21 20:18:38.721464 [NOTICE] switch_core_session.c:1560 Session 44
(sofia/internal/1002 at domain.com) Ended
2013-07-21 20:18:38.721464 [NOTICE] switch_core_session.c:1564 Close Channel
sofia/internal/1002 at domain.com [CS_DESTROY]
2013-07-21 20:18:38.721464 [DEBUG] switch_core_state_machine.c:565
(sofia/internal/1002 at domain.com) Callstate Change HANGUP -> DOWN
2013-07-21 20:18:38.721464 [DEBUG] switch_core_state_machine.c:568
(sofia/internal/1002 at domain.com) Running State Change CS_DESTROY
2013-07-21 20:18:38.721464 [DEBUG] switch_core_state_machine.c:578
(sofia/internal/1002 at domain.com) State DESTROY
2013-07-21 20:18:38.721464 [DEBUG] mod_sofia.c:397
sofia/internal/1002 at domain.com SOFIA DESTROY
2013-07-21 20:18:38.721464 [DEBUG] switch_core_state_machine.c:99
sofia/internal/1002 at domain.com Standard DESTROY
2013-07-21 20:18:38.721464 [DEBUG] switch_core_state_machine.c:578
(sofia/internal/1002 at domain.com) State DESTROY going to sleep

--
View this message in context: http://freeswitch-users.2379917.n2.nabble.com/FS-not-supporting-ZRTP-MITM-tp7593067.html
Sent from the freeswitch-users mailing list archive at Nabble.com.