Hi all, When dialing with Acrobits/iPhone app I get most of the times ZRTP errors when making outgoing/incoming calls via Freeswitch. The app starts ZRTP key exchange and then stops with ZRTP error message. Sometimes it works but most of the time it does not. I'm using GSM and PCMU codecs (20sec) on both Acrobits and Freeswitch. Is there a special ZRTP/dialplan setup for Acrobits/iPhone app? Using none acrobits apps with ZRTP on Android with no issues. Here is my dialplan for the incoming call from DID 722157185 to extension 99556678, and FS debug flow which shows the ZRTP error cause: [zrtp respond]: INFO: Authtag HS80 isn't supported by profile. ID=1551 Regards Assaf <?xml version='1.0' encoding='UTF-8' standalone='no'?> <document type='freeswitch/xml'> <section name='dialplan' description='CALL Routing request'> <context name='external'> <extension name='call_to_99556678'> <condition field='destination_number' expression='^722157185$'> <action application='set' data='call_timeout=45'/><action application='set' data='ringback=${us-ring}'/><action application='set' data='instant_ringback=true'/><action application='set' data='x_dst_tariff='/><action application='set' data='x_dialplan_mode=PLIVO-FS'/><action application='set' data='x_account_id=0'/><action application='set' data='effective_caller_id_number=0542526278'/><action application='set' data='effective_caller_id_name='/><action application='set' data='zrtp_secure_media=true'/><action application='set' data='zrtp_enrollment=true'/><action application='set' data='x_call_type=PSTN2SIP'/><action application='set' data='x_user_name=99556678'/><action application='set' data='x_domain_name=confidentialtele.com'/><action application='set' data='proxy_media=false'/><action application='set' data='execute_on_answer=sched_hangup +3600 alloted_timeout' /><action application='set' data='hangup_after_bridge=true'/><action application='set' data='continue_on_fail=true'/><action application='bridge' data='user/99556678@confidentialtele.com' /> </condition> </extension> </context> </section> </document> 2015-08-18 07:33:58.946068 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:33:58.946068 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:415 (sofia/external/0542526278@212.199.157.154:5060) Running State Change CS_NEW 2015-08-18 07:33:58.946068 [DEBUG] sofia.c:7877 sofia/external/0542526278@212.199.157.154:5060 receiving invite from 212.199.157.154:5060 version: 1.2.22 git 468dc29 2014-03-14 21:23:27Z 64bit 2015-08-18 07:33:58.946068 [DEBUG] sofia.c:5815 Channel sofia/external/0542526278@212.199.157.154:5060 entering state [received][100] 2015-08-18 07:33:58.946068 [DEBUG] sofia.c:5828 Remote SDP: v=0 o=Sonus_UAC 25651 22274 IN IP4 212.199.157.154 s=SIP Media Capabilities c=IN IP4 212.199.157.155 t=0 0 m=audio 28286 RTP/AVP 18 8 0 100 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-15 a=maxptime:20 2015-08-18 07:33:58.946068 [DEBUG] sofia.c:6075 (sofia/external/0542526278@212.199.157.154:5060) State Change CS_NEW -> CS_INIT 2015-08-18 07:33:58.946068 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:434 (sofia/external/0542526278@212.199.157.154:5060) State NEW 2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:415 (sofia/external/0542526278@212.199.157.154:5060) Running State Change CS_INIT 2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:455 (sofia/external/0542526278@212.199.157.154:5060) State INIT 2015-08-18 07:33:58.946068 [DEBUG] mod_sofia.c:87 sofia/external/0542526278@212.199.157.154:5060 SOFIA INIT 2015-08-18 07:33:58.946068 [DEBUG] mod_sofia.c:127 (sofia/external/0542526278@212.199.157.154:5060) State Change CS_INIT -> CS_ROUTING 2015-08-18 07:33:58.946068 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:455 (sofia/external/0542526278@212.199.157.154:5060) State INIT going to sleep 2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:415 (sofia/external/0542526278@212.199.157.154:5060) Running State Change CS_ROUTING 2015-08-18 07:33:58.946068 [DEBUG] switch_channel.c:2163 (sofia/external/0542526278@212.199.157.154:5060) Callstate Change DOWN -> RINGING 2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:471 (sofia/external/0542526278@212.199.157.154:5060) State ROUTING 2015-08-18 07:33:58.946068 [DEBUG] mod_sofia.c:150 sofia/external/0542526278@212.199.157.154:5060 SOFIA ROUTING 2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:117 sofia/external/0542526278@212.199.157.154:5060 Standard ROUTING 2015-08-18 07:33:58.946068 [INFO] mod_dialplan_xml.c:558 Processing 0542526278 <0542526278>->722157185 in context external Dialplan: sofia/external/0542526278@212.199.157.154:5060 parsing [external->call_to_99556678] continue=false Dialplan: sofia/external/0542526278@212.199.157.154:5060 Regex (PASS) [call_to_99556678] destination_number(722157185) =~ /^722157185$/ break=on-false Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(call_timeout=45) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(ringback=${us-ring}) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(instant_ringback=true) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(x_dst_tariff=) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(x_dialplan_mode=PLIVO-FS) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(x_account_id=0) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(effective_caller_id_number=0542526278) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(effective_caller_id_name=) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(zrtp_secure_media=true) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(zrtp_enrollment=true) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(x_call_type=PSTN2SIP) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(x_user_name=99556678) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(x_domain_name=confidentialtele.com) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(proxy_media=false) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(execute_on_answer=sched_hangup +3600 alloted_timeout) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(hangup_after_bridge=true) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action set(continue_on_fail=true) Dialplan: sofia/external/0542526278@212.199.157.154:5060 Action bridge(user/99556678@confidentialtele.com) 2015-08-18 07:33:58.986050 [DEBUG] switch_core_state_machine.c:167 (sofia/external/0542526278@212.199.157.154:5060) State Change CS_ROUTING -> CS_EXECUTE 2015-08-18 07:33:58.986050 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:33:58.986050 [DEBUG] switch_core_state_machine.c:471 (sofia/external/0542526278@212.199.157.154:5060) State ROUTING going to sleep 2015-08-18 07:33:58.986050 [DEBUG] switch_core_state_machine.c:415 (sofia/external/0542526278@212.199.157.154:5060) Running State Change CS_EXECUTE 2015-08-18 07:33:58.986050 [DEBUG] switch_core_state_machine.c:478 (sofia/external/0542526278@212.199.157.154:5060) State EXECUTE 2015-08-18 07:33:58.986050 [DEBUG] mod_sofia.c:243 sofia/external/0542526278@212.199.157.154:5060 SOFIA EXECUTE 2015-08-18 07:33:58.986050 [DEBUG] switch_core_state_machine.c:209 sofia/external/0542526278@212.199.157.154:5060 Standard EXECUTE EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(call_timeout=45) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [call_timeout]=[45] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(ringback=%(2000,4000,440,480)) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(instant_ringback=true) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [instant_ringback]=[true] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(x_dst_tariff=) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [x_dst_tariff]=[UNDEF] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(x_dialplan_mode=PLIVO-FS) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [x_dialplan_mode]=[PLIVO-FS] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(x_account_id=0) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [x_account_id]=[0] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(effective_caller_id_number=0542526278) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [effective_caller_id_number]=[0542526278] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(effective_caller_id_name=) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [effective_caller_id_name]=[UNDEF] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(zrtp_secure_media=true) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [zrtp_secure_media]=[true] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(zrtp_enrollment=true) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [zrtp_enrollment]=[true] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(x_call_type=PSTN2SIP) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [x_call_type]=[PSTN2SIP] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(x_user_name=99556678) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [x_user_name]=[99556678] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(x_domain_name=confidentialtele.com) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [x_domain_name]=[confidentialtele.com] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(proxy_media=false) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [proxy_media]=[false] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(execute_on_answer=sched_hangup +3600 alloted_timeout) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [execute_on_answer]=[sched_hangup +3600 alloted_timeout] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(hangup_after_bridge=true) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [hangup_after_bridge]=[true] EXECUTE sofia/external/0542526278@212.199.157.154:5060 set(continue_on_fail=true) 2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402 sofia/external/0542526278@212.199.157.154:5060 SET [continue_on_fail]=[true] EXECUTE sofia/external/0542526278@212.199.157.154:5060 bridge(user/99556678@confidentialtele.com) 2015-08-18 07:33:58.986050 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2015-08-18 07:33:59.017997 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2015-08-18 07:33:59.017997 [DEBUG] switch_event.c:1661 Parsing variable [presence_id]=[99556678@confidentialtele.com] 2015-08-18 07:33:59.017997 [NOTICE] switch_channel.c:1050 New Channel sofia/agents/sip:99556678@164.138.115.183:50214 [58014df2-4562-11e5-b0c3-e7d40967f7d3] 2015-08-18 07:33:59.017997 [DEBUG] mod_sofia.c:5236 (sofia/agents/sip:99556678@164.138.115.183:50214) State Change CS_NEW -> CS_INIT 2015-08-18 07:33:59.017997 [DEBUG] switch_core_session.c:1351 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:33:59.017997 [DEBUG] mod_sofia.c:5306 [zrtp_passthru] Setting a-leg inherit_codec=true 2015-08-18 07:33:59.017997 [DEBUG] mod_sofia.c:5309 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMU@8000h@20i@64000b' 2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:415 (sofia/agents/sip:99556678@164.138.115.183:50214) Running State Change CS_INIT 2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:455 (sofia/agents/sip:99556678@164.138.115.183:50214) State INIT 2015-08-18 07:33:59.017997 [DEBUG] mod_sofia.c:87 sofia/agents/sip:99556678@164.138.115.183:50214 SOFIA INIT 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:2716 sip:99556678@164.138.115.183:50214;rinstance=1E740845;transport=tls Setting proxy route to sofia/agents/sip:99556678@164.138.115.183:50214 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:2744 sofia/agents/sip:99556678@164.138.115.183:50214 sending invite version: 1.2.22 git 468dc29 2014-03-14 21:23:27Z 64bit Local SDP: v=0 o=FreeSWITCH 1439860069 1439860070 IN IP4 82.80.217.142 s=FreeSWITCH c=IN IP4 82.80.217.142 t=0 0 m=audio 12370 RTP/AVP 0 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2015-08-18 07:33:59.017997 [DEBUG] mod_sofia.c:127 (sofia/agents/sip:99556678@164.138.115.183:50214) State Change CS_INIT -> CS_ROUTING 2015-08-18 07:33:59.017997 [DEBUG] switch_core_session.c:1351 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:455 (sofia/agents/sip:99556678@164.138.115.183:50214) State INIT going to sleep 2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:415 (sofia/agents/sip:99556678@164.138.115.183:50214) Running State Change CS_ROUTING 2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:471 (sofia/agents/sip:99556678@164.138.115.183:50214) State ROUTING 2015-08-18 07:33:59.017997 [DEBUG] mod_sofia.c:150 sofia/agents/sip:99556678@164.138.115.183:50214 SOFIA ROUTING 2015-08-18 07:33:59.017997 [DEBUG] switch_ivr_originate.c:67 (sofia/agents/sip:99556678@164.138.115.183:50214) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2015-08-18 07:33:59.017997 [DEBUG] switch_core_session.c:1351 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:471 (sofia/agents/sip:99556678@164.138.115.183:50214) State ROUTING going to sleep 2015-08-18 07:33:59.017997 [DEBUG] switch_core_session.c:1016 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:33:59.017997 [INFO] switch_ivr_originate.c:1191 Sending early media 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [G729:18:8000:20:8000]/[SILK:117:8000:20:20000] 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [G729:18:8000:20:8000]/[GSM:3:8000:20:13200] 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [G729:18:8000:20:8000]/[PCMU:0:8000:20:64000] 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMA:8:8000:20:64000]/[SILK:117:8000:20:20000] 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMA:8:8000:20:64000]/[GSM:3:8000:20:13200] 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000] 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[SILK:117:8000:20:20000] 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[GSM:3:8000:20:13200] 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:3190 Set Codec sofia/external/0542526278@212.199.157.154:5060 PCMU/8000 20 ms 160 samples 64000 bits 2015-08-18 07:33:59.017997 [DEBUG] switch_core_codec.c:111 sofia/external/0542526278@212.199.157.154:5060 Original read codec set to PCMU:0 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:5451 Set 2833 dtmf send/recv payload to 100 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:3449 AUDIO RTP [sofia/external/0542526278@212.199.157.154:5060] 82.80.217.142 port 10872 -> 212.199.157.155 port 28286 codec: 0 ms: 20 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:2040 Starting timer [soft] 160 bytes per 20ms 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: START SESSION INITIALIZATION. sID=1550. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: ZID=353235306439386564366363. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: Loading User's profile: 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: allowclear: OFF 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: autosecure: ON 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: disclose_bit: OFF 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: signal. role: Unknown 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: TTL: 4294967295 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: SAS schemes: 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 B256 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 B32 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: Ciphers: 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 AES3 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 AES1 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: PK schemes: 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 EC25 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 DH3k 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 DH2k 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 Mult 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: ATL: 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 HS32 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: Hashes: 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 S256 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: Session initialization - DONE. sID=1550. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: ATTACH NEW STREAM to sID=1550: 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: Empty slot was found - initializing new stream with ID=1550. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: Preparing ZRTP Hello according to the Session profile. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp main]: ATTACH NEW STREAM - DONE. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp mitm]: START REGISTRATION STREAM ID=1550 mode=CLEAR state=ACTIVE. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp engine]: START STREAM ID=1550 mode=CLEAR state=ACTIVE. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=1550 CLEAR switching <ACTIVE> ---> <START>. 2015-08-18 07:33:59.017997 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15607 size=144. Stream 1550:CLEAR:START 2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:415 (sofia/agents/sip:99556678@164.138.115.183:50214) Running State Change CS_CONSUME_MEDIA 2015-08-18 07:33:59.017997 [DEBUG] sofia.c:5815 Channel sofia/agents/sip:99556678@164.138.115.183:50214 entering state [calling][0] 2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:490 (sofia/agents/sip:99556678@164.138.115.183:50214) State CONSUME_MEDIA 2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:490 (sofia/agents/sip:99556678@164.138.115.183:50214) State CONSUME_MEDIA going to sleep 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:3716 Set 2833 dtmf send payload to 100 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:3722 Set 2833 dtmf receive payload to 100 2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:3749 sofia/external/0542526278@212.199.157.154:5060 Set rtp dtmf delay to 40 2015-08-18 07:33:59.017997 [NOTICE] sofia_glue.c:4360 Pre-Answer sofia/external/0542526278@212.199.157.154:5060! 2015-08-18 07:33:59.017997 [DEBUG] switch_channel.c:3368 (sofia/external/0542526278@212.199.157.154:5060) Callstate Change RINGING -> EARLY 2015-08-18 07:33:59.017997 [DEBUG] mod_sofia.c:2891 Ring SDP: v=0 o=FreeSWITCH 1439861567 1439861568 IN IP4 82.80.217.142 s=FreeSWITCH c=IN IP4 82.80.217.142 t=0 0 m=audio 10872 RTP/AVP 0 100 a=rtpmap:0 PCMU/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-16 a=ptime:20 a=sendrecv 2015-08-18 07:33:59.017997 [DEBUG] switch_core_session.c:871 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:33:59.017997 [DEBUG] switch_ivr_originate.c:1248 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2015-08-18 07:33:59.017997 [DEBUG] switch_core_codec.c:219 sofia/external/0542526278@212.199.157.154:5060 Push codec L16:70 2015-08-18 07:33:59.017997 [DEBUG] switch_ivr_originate.c:1316 Play Ringback Tone [%(2000,4000,440,480)] 2015-08-18 07:33:59.017997 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:33:59.056050 [DEBUG] sofia.c:5815 Channel sofia/external/0542526278@212.199.157.154:5060 entering state [early][183] 2015-08-18 07:33:59.086039 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15608 size=144. Stream 1550:CLEAR:START 2015-08-18 07:33:59.126047 [DEBUG] switch_core_session.c:1016 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:33:59.126047 [DEBUG] switch_core_session.c:1016 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:33:59.126047 [DEBUG] sofia.c:5815 Channel sofia/agents/sip:99556678@164.138.115.183:50214 entering state [proceeding][180] 2015-08-18 07:33:59.126047 [NOTICE] sofia.c:5910 Ring-Ready sofia/agents/sip:99556678@164.138.115.183:50214! 2015-08-18 07:33:59.126047 [DEBUG] switch_channel.c:3242 (sofia/agents/sip:99556678@164.138.115.183:50214) Callstate Change DOWN -> RINGING 2015-08-18 07:33:59.186036 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15609 size=144. Stream 1550:CLEAR:START 2015-08-18 07:33:59.236037 [DEBUG] switch_rtp.c:3757 Correct ip/port confirmed. 2015-08-18 07:33:59.386038 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15610 size=144. Stream 1550:CLEAR:START 2015-08-18 07:33:59.586037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15611 size=144. Stream 1550:CLEAR:START 2015-08-18 07:33:59.786037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: WARNING! HELLO have been resent 5 times without a response. Raising ZRTP_EVENT_NO_ZRTP_QUICK event. ID=1550 2015-08-18 07:33:59.786037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15612 size=144. Stream 1550:CLEAR:START 2015-08-18 07:33:59.986037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15613 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:00.196037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15614 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:00.396036 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15615 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:00.596037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15616 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:00.796050 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15617 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:00.996036 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15618 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:01.196037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15619 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:01.396050 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15620 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:01.596036 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15621 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:01.796036 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15622 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:01.996050 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15623 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:02.196037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15624 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:02.396050 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15625 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:02.596050 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3923818383 seq=15626 size=144. Stream 1550:CLEAR:START 2015-08-18 07:34:02.636038 [DEBUG] switch_core_session.c:1016 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:02.636038 [DEBUG] switch_core_session.c:1016 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:02.636038 [DEBUG] sofia.c:5815 Channel sofia/agents/sip:99556678@164.138.115.183:50214 entering state [completing][200] 2015-08-18 07:34:02.636038 [DEBUG] sofia.c:5828 Remote SDP: v=0 o=- 8706103222 65422 IN IP4 172.26.170.170 s=vzrqxyq c=IN IP4 10.0.0.16 t=0 0 m=audio 48928 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2015-08-18 07:34:02.636038 [DEBUG] switch_core_session.c:1016 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:02.636038 [DEBUG] switch_core_session.c:1016 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:02.636038 [DEBUG] sofia.c:5815 Channel sofia/agents/sip:99556678@164.138.115.183:50214 entering state [ready][200] 2015-08-18 07:34:02.636038 [DEBUG] sofia_glue.c:5282 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2015-08-18 07:34:02.636038 [DEBUG] sofia_glue.c:3190 Set Codec sofia/agents/sip:99556678@164.138.115.183:50214 PCMU/8000 20 ms 160 samples 64000 bits 2015-08-18 07:34:02.636038 [DEBUG] switch_core_codec.c:111 sofia/agents/sip:99556678@164.138.115.183:50214 Original read codec set to PCMU:0 2015-08-18 07:34:02.636038 [DEBUG] sofia_glue.c:5442 Set 2833 dtmf send payload to 101 2015-08-18 07:34:02.636038 [DEBUG] sofia_glue.c:3449 AUDIO RTP [sofia/agents/sip:99556678@164.138.115.183:50214] 82.80.217.142 port 12370 -> 10.0.0.16 port 48928 codec: 0 ms: 20 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:2040 Starting timer [soft] 160 bytes per 20ms 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: START SESSION INITIALIZATION. sID=1551. 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: ZID=353235306439386564366363. 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: Loading User's profile: 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: allowclear: OFF 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: autosecure: ON 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: disclose_bit: OFF 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: signal. role: Initiator 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: TTL: 4294967295 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: SAS schemes: 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 B256 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 B32 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: Ciphers: 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 AES3 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 AES1 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: PK schemes: 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 EC25 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 DH3k 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 DH2k 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 Mult 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: ATL: 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 HS32 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 [ zrtp main]: Hashes: 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 S256 2015-08-18 07:34:02.636038 [DEBUG] switch_rtp.c:948 2015-08-18 07:34:02.646130 [DEBUG] switch_rtp.c:948 [ zrtp main]: Session initialization - DONE. sID=1551. 2015-08-18 07:34:02.646130 [DEBUG] switch_rtp.c:948 [ zrtp main]: ATTACH NEW STREAM to sID=1551: 2015-08-18 07:34:02.646130 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>. 2015-08-18 07:34:02.646130 [DEBUG] switch_rtp.c:948 [ zrtp main]: Empty slot was found - initializing new stream with ID=1551. 2015-08-18 07:34:02.646130 [DEBUG] switch_rtp.c:948 [ zrtp main]: Preparing ZRTP Hello according to the Session profile. 2015-08-18 07:34:02.646130 [DEBUG] switch_rtp.c:948 [ zrtp main]: ATTACH NEW STREAM - DONE. 2015-08-18 07:34:02.646130 [DEBUG] switch_rtp.c:948 [ zrtp engine]: START STREAM ID=1551 mode=CLEAR state=ACTIVE. 2015-08-18 07:34:02.646130 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=1551 CLEAR switching <ACTIVE> ---> <START>. 2015-08-18 07:34:02.646130 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3992876290 seq=8297 size=144. Stream 1551:CLEAR:START 2015-08-18 07:34:02.646130 [DEBUG] sofia_glue.c:3716 Set 2833 dtmf send payload to 101 2015-08-18 07:34:02.646130 [DEBUG] sofia_glue.c:3722 Set 2833 dtmf receive payload to 101 2015-08-18 07:34:02.646130 [DEBUG] sofia_glue.c:3749 sofia/agents/sip:99556678@164.138.115.183:50214 Set rtp dtmf delay to 40 2015-08-18 07:34:02.646130 [DEBUG] switch_channel.c:3601 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:02.646130 [NOTICE] sofia.c:6604 Channel [sofia/agents/sip:99556678@164.138.115.183:50214] has been answered 2015-08-18 07:34:02.646130 [DEBUG] switch_channel.c:3647 (sofia/agents/sip:99556678@164.138.115.183:50214) Callstate Change RINGING -> ACTIVE 2015-08-18 07:34:02.656044 [DEBUG] switch_core_codec.c:244 sofia/external/0542526278@212.199.157.154:5060 Restore previous codec PCMU:0. 2015-08-18 07:34:02.656044 [DEBUG] mod_sofia.c:866 Local SDP sofia/external/0542526278@212.199.157.154:5060: v=0 o=FreeSWITCH 1439861567 1439861569 IN IP4 82.80.217.142 s=FreeSWITCH c=IN IP4 82.80.217.142 t=0 0 m=audio 10872 RTP/AVP 0 100 a=rtpmap:0 PCMU/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-16 a=ptime:20 a=sendrecv 2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:871 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:02.656044 [NOTICE] switch_ivr_originate.c:3456 Channel [sofia/external/0542526278@212.199.157.154:5060] has been answered EXECUTE sofia/external/0542526278@212.199.157.154:5060 sched_hangup(+3600 alloted_timeout) 2015-08-18 07:34:02.656044 [DEBUG] switch_scheduler.c:243 Added task 790 switch_ivr_schedule_hangup (57f517c6-4562-11e5-b0a7-e7d40967f7d3) to run at 1439876042 2015-08-18 07:34:02.656044 [DEBUG] switch_channel.c:3647 (sofia/external/0542526278@212.199.157.154:5060) Callstate Change EARLY -> ACTIVE 2015-08-18 07:34:02.656044 [DEBUG] switch_ivr_originate.c:3513 Originate Resulted in Success: [sofia/agents/sip:99556678@164.138.115.183:50214] 2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:02.656044 [DEBUG] sofia.c:5815 Channel sofia/external/0542526278@212.199.157.154:5060 entering state [completed][200] 2015-08-18 07:34:02.656044 [DEBUG] switch_ivr_originate.c:3513 Originate Resulted in Success: [sofia/agents/sip:99556678@164.138.115.183:50214] 2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:871 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:871 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:02.656044 [DEBUG] switch_ivr_bridge.c:1446 (sofia/agents/sip:99556678@164.138.115.183:50214) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:1351 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:02.656044 [DEBUG] switch_core_state_machine.c:415 (sofia/agents/sip:99556678@164.138.115.183:50214) Running State Change CS_EXCHANGE_MEDIA 2015-08-18 07:34:02.656044 [DEBUG] switch_core_state_machine.c:481 (sofia/agents/sip:99556678@164.138.115.183:50214) State EXCHANGE_MEDIA 2015-08-18 07:34:02.656044 [DEBUG] mod_sofia.c:688 SOFIA EXCHANGE_MEDIA 2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:02.696047 [DEBUG] sofia.c:5815 Channel sofia/external/0542526278@212.199.157.154:5060 entering state [ready][200] 2015-08-18 07:34:02.696047 [DEBUG] switch_core_session.c:933 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:02.696047 [DEBUG] switch_core_session.c:933 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:02.696047 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3992876290 seq=8298 size=144. Stream 1551:CLEAR:START 2015-08-18 07:34:02.796037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=1550 2015-08-18 07:34:02.796037 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=1550 CLEAR switching <START> ---> <NOZRTP>. 2015-08-18 07:34:02.816038 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3992876290 seq=8299 size=144. Stream 1551:CLEAR:START 2015-08-18 07:34:02.896037 [INFO] switch_rtp.c:3738 Auto Changing port from 10.0.0.16:48928 to 164.138.115.183:48928 2015-08-18 07:34:03.026038 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=3992876290 seq=8300 size=144. Stream 1551:CLEAR:START 2015-08-18 07:34:03.116037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Received <HelloACK> packet with ssrc=1504409235 seq=59645/59645 size=28. Stream1551:CLEAR:START. 2015-08-18 07:34:03.116037 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=1551 CLEAR switching <START> ---> <W4HELLO>. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Received <Hello > packet with ssrc=1504409235 seq=59644/59644 size=136. Stream1551:CLEAR:W4HELLO. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Processing HELLO from Acrobits/1.0 V=1.10, P=0, M=0. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: ac=1 cc=1 sc=2 kc=2 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: S256S384AES3HS80EC38DH3kB256B32 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Received HELLO had the same protocol V. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: _zrtp_choose_best_comp() for PKT. local=DH3k remote=DH3k, choosen=DH3k 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Received HELLO Accepted 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp cache]: ache_get(): zid1=353235306439386564366363, zis2=1d786c7acc41df3254401114 MiTM=NO 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp cache]: ache_get(): zid1=353235306439386564366363, zis2=1d786c7acc41df3254401114 MiTM=NO 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp cache]: ache_get() - not found. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp cache]: ache_get(): zid1=353235306439386564366363, zis2=1d786c7acc41df3254401114 MiTM=YES 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Restoring Secrets: lZID=353235306439386564366363 rZID=1d786c7acc41df3254401114. V=1 sID=1551 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: RS1 <d4b34c062dde89f9779ebd04e5dc21f6ac8876ac00a4a483732839883c3a97ff> 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: RS2 <EMPTY> 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: PBX <53b18d74e55ed6eaa28bff74c4f244f25b61cc6ec84e38fe918215e7b3b3e271> 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=1551 CLEAR switching <W4HELLO> ---> <SINITSEC>. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Initiating Secure iteration... ID=1551. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Got mode=DH. Check approval of starting. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Mode=DH Cccepted. Starting ZRTP Initiator Protocol. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [zrtp initiat]: ENTER STATE INITIATING SECURE for ID=1551 mode=DH state=SINITSEC. 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [zrtp initiat]: Initiator selected following options: 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [zrtp initiat]: Hash: S256 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [zrtp initiat]: Cipher: AES3 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [zrtp initiat]: ATL: HS32 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [zrtp initiat]: VAD scheme: B256 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [zrtp protoco]: Init INITIATOR's Protocol ID=1551 mode=DH... 2015-08-18 07:34:03.136037 [DEBUG] switch_rtp.c:948 [ zrtp dh]: DH TEST: DH3k zrtp_dh_initialize() START. now=1439872443136ms. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [ zrtp dh]: DH TEST: zrtp_dh_initialize() for DH3k was executed ts=1439872443150ms d=14ms. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp protoco]: Attach RS id=99f73649cd19c2cc. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp protoco]: Attach RS peer_id=4528027f7cf5ae69. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp protoco]: Attach RS id=5273a6e53041d6e2. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp protoco]: Attach RS peer_id=37fae36a5b9499d7. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp protoco]: Attach RS id=bfebfc14937ab973. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp protoco]: Attach RS peer_id=b3d1fc6634723ece. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp protoco]: Attach RS id=91efde175d88dd1b. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp protoco]: Attach RS peer_id=f77b9dcbaa3856d6. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=1551 DH switching <SINITSEC> ---> <INITSEC>. 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp initiat]: Start Sending COMMIT ID=1551 mode=DH state=INITSEC: 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp initiat]: Hash: S256 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp initiat]: Cipher: AES3 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp initiat]: ATL: HS32 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp initiat]: PK scheme: DH3k 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp initiat]: VAD scheme: B256 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [zrtp initiat]: hv: 6079e170ef33b35d7d4a03da8c0f072ab09940e0b5d4754973b111033c57c695 2015-08-18 07:34:03.146042 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <COMMIT> ssrc=3992876290 seq=8301 size=132. Stream 1551:DH:INITSEC 2015-08-18 07:34:03.156039 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.176038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.196038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.216041 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.236047 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.256038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.276038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.296038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.306040 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <COMMIT> ssrc=3992876290 seq=8302 size=132. Stream 1551:DH:INITSEC 2015-08-18 07:34:03.316039 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.336038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.356038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.376038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.396038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.416037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.436038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.456038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.476038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.496038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.516037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.536038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.556038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.576038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.596038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.606040 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <COMMIT> ssrc=3992876290 seq=8303 size=132. Stream 1551:DH:INITSEC 2015-08-18 07:34:03.616040 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.636038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.656039 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.676038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.696037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.716043 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.736038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.756038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.776038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.796051 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.816051 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.836053 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.856090 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.876038 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.896037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.916037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.936037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Add 172 bytes of entropy to the RNG pool. 2015-08-18 07:34:03.936037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Received <Commit > packet with ssrc=1504409235 seq=59646/59646 size=132. Stream1551:DH:INITSEC. 2015-08-18 07:34:03.936037 [DEBUG] switch_rtp.c:948 [zrtp respond]: Preparse incoming COMMIT. Remote peer wants DH3k:2 mode lic=1 peer M=0. 2015-08-18 07:34:03.936037 [DEBUG] switch_rtp.c:948 [zrtp respond]: INFO: Authtag HS80 isn't supported by profile. ID=1551 2015-08-18 07:34:03.936037 [DEBUG] switch_rtp.c:948 [ zrtp engine]: Enter InitiatingError State with ERROR:<SRTP auth. tag not supported>, notification Enabled. ID=1551 2015-08-18 07:34:03.936037 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=1551 DH switching <INITSEC> ---> <INITERROR>. 2015-08-18 07:34:03.936037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <ERROR> ssrc=3992876290 seq=8304 size=32. Stream 1551:DH:INITERROR 2015-08-18 07:34:03.956037 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Received <ErrorACK> packet with ssrc=1504409235 seq=59648/59648 size=28. Stream1551:DH:INITERROR. 2015-08-18 07:34:03.956037 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=1551 DH switching <INITERROR> ---> <ERROR>. 2015-08-18 07:34:03.966040 [DEBUG] switch_core_session.c:1016 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:03.976040 [NOTICE] sofia.c:737 Hangup sofia/agents/sip:99556678@164.138.115.183:50214 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2015-08-18 07:34:03.976040 [DEBUG] switch_channel.c:3187 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [KILL] 2015-08-18 07:34:03.976040 [DEBUG] switch_core_session.c:1351 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:03.976040 [DEBUG] switch_ivr_bridge.c:645 BRIDGE THREAD DONE [sofia/agents/sip:99556678@164.138.115.183:50214] 2015-08-18 07:34:03.976040 [DEBUG] switch_ivr_bridge.c:675 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:481 (sofia/agents/sip:99556678@164.138.115.183:50214) State EXCHANGE_MEDIA going to sleep 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:415 (sofia/agents/sip:99556678@164.138.115.183:50214) Running State Change CS_HANGUP 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:678 (sofia/agents/sip:99556678@164.138.115.183:50214) Callstate Change ACTIVE -> HANGUP 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:680 (sofia/agents/sip:99556678@164.138.115.183:50214) State HANGUP 2015-08-18 07:34:03.976040 [DEBUG] mod_sofia.c:506 Channel sofia/agents/sip:99556678@164.138.115.183:50214 hanging up, cause: NORMAL_CLEARING 2015-08-18 07:34:03.976040 [DEBUG] switch_ivr_bridge.c:569 sofia/agents/sip:99556678@164.138.115.183:50214 ending bridge by request from write function 2015-08-18 07:34:03.976040 [DEBUG] switch_ivr_bridge.c:645 BRIDGE THREAD DONE [sofia/external/0542526278@212.199.157.154:5060] 2015-08-18 07:34:03.976040 [DEBUG] switch_ivr_bridge.c:675 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:03.976040 [DEBUG] switch_ivr_bridge.c:1544 sofia/agents/sip:99556678@164.138.115.183:50214 skip receive message [UNBRIDGE] (channel is hungup already) 2015-08-18 07:34:03.976040 [DEBUG] switch_core_session.c:871 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:48 sofia/agents/sip:99556678@164.138.115.183:50214 Standard HANGUP, cause: NORMAL_CLEARING 2015-08-18 07:34:03.976040 [NOTICE] switch_ivr_bridge.c:1589 Hangup sofia/external/0542526278@212.199.157.154:5060 [CS_EXECUTE] [NORMAL_CLEARING] 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:680 (sofia/agents/sip:99556678@164.138.115.183:50214) State HANGUP going to sleep 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:447 (sofia/agents/sip:99556678@164.138.115.183:50214) State Change CS_HANGUP -> CS_REPORTING 2015-08-18 07:34:03.976040 [DEBUG] switch_core_session.c:1351 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:03.976040 [DEBUG] switch_channel.c:3187 Send signal sofia/external/0542526278@212.199.157.154:5060 [KILL] 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:415 (sofia/agents/sip:99556678@164.138.115.183:50214) Running State Change CS_REPORTING 2015-08-18 07:34:03.976040 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:764 (sofia/agents/sip:99556678@164.138.115.183:50214) State REPORTING 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:92 sofia/agents/sip:99556678@164.138.115.183:50214 Standard REPORTING, cause: NORMAL_CLEARING 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:764 (sofia/agents/sip:99556678@164.138.115.183:50214) State REPORTING going to sleep 2015-08-18 07:34:03.976040 [DEBUG] switch_core_session.c:2810 sofia/external/0542526278@212.199.157.154:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:478 (sofia/external/0542526278@212.199.157.154:5060) State EXECUTE going to sleep 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:415 (sofia/external/0542526278@212.199.157.154:5060) Running State Change CS_HANGUP 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:678 (sofia/external/0542526278@212.199.157.154:5060) Callstate Change ACTIVE -> HANGUP 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:441 (sofia/agents/sip:99556678@164.138.115.183:50214) State Change CS_REPORTING -> CS_DESTROY 2015-08-18 07:34:03.976040 [DEBUG] switch_core_session.c:1351 Send signal sofia/agents/sip:99556678@164.138.115.183:50214 [BREAK] 2015-08-18 07:34:03.976040 [DEBUG] switch_core_session.c:1559 Session 5559 (sofia/agents/sip:99556678@164.138.115.183:50214) Locked, Waiting on external entities 2015-08-18 07:34:03.976040 [NOTICE] switch_core_session.c:1577 Session 5559 (sofia/agents/sip:99556678@164.138.115.183:50214) Ended 2015-08-18 07:34:03.976040 [NOTICE] switch_core_session.c:1581 Close Channel sofia/agents/sip:99556678@164.138.115.183:50214 [CS_DESTROY] 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:680 (sofia/external/0542526278@212.199.157.154:5060) State HANGUP 2015-08-18 07:34:03.976040 [DEBUG] mod_sofia.c:500 sofia/external/0542526278@212.199.157.154:5060 Overriding SIP cause 480 with 200 from the other leg 2015-08-18 07:34:03.976040 [DEBUG] mod_sofia.c:506 Channel sofia/external/0542526278@212.199.157.154:5060 hanging up, cause: NORMAL_CLEARING 2015-08-18 07:34:03.976040 [DEBUG] mod_sofia.c:558 Sending BYE to sofia/external/0542526278@212.199.157.154:5060 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:48 sofia/external/0542526278@212.199.157.154:5060 Standard HANGUP, cause: NORMAL_CLEARING 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:680 (sofia/external/0542526278@212.199.157.154:5060) State HANGUP going to sleep 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:447 (sofia/external/0542526278@212.199.157.154:5060) State Change CS_HANGUP -> CS_REPORTING 2015-08-18 07:34:03.976040 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:415 (sofia/external/0542526278@212.199.157.154:5060) Running State Change CS_REPORTING 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:764 (sofia/external/0542526278@212.199.157.154:5060) State REPORTING 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:566 (sofia/agents/sip:99556678@164.138.115.183:50214) Callstate Change HANGUP -> DOWN 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:569 (sofia/agents/sip:99556678@164.138.115.183:50214) Running State Change CS_DESTROY 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:579 (sofia/agents/sip:99556678@164.138.115.183:50214) State DESTROY 2015-08-18 07:34:03.976040 [DEBUG] mod_sofia.c:399 sofia/agents/sip:99556678@164.138.115.183:50214 SOFIA DESTROY 2015-08-18 07:34:03.976040 [DEBUG] switch_rtp.c:948 [ zrtp engine]: STOP STREAM ID=1551 mode=DH state=ERROR. 2015-08-18 07:34:03.976040 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <NONE>. 2015-08-18 07:34:03.976040 [DEBUG] switch_rtp.c:948 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE. 2015-08-18 07:34:03.976040 [DEBUG] switch_rtp.c:948 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE. 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:99 sofia/agents/sip:99556678@164.138.115.183:50214 Standard DESTROY 2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:579 (sofia/agents/sip:99556678@164.138.115.183:50214) State DESTROY going to sleep 2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:92 sofia/external/0542526278@212.199.157.154:5060 Standard REPORTING, cause: NORMAL_CLEARING 2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:764 (sofia/external/0542526278@212.199.157.154:5060) State REPORTING going to sleep 2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:441 (sofia/external/0542526278@212.199.157.154:5060) State Change CS_REPORTING -> CS_DESTROY 2015-08-18 07:34:04.056039 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0542526278@212.199.157.154:5060 [BREAK] 2015-08-18 07:34:04.056039 [DEBUG] switch_core_session.c:1559 Session 5558 (sofia/external/0542526278@212.199.157.154:5060) Locked, Waiting on external entities 2015-08-18 07:34:04.056039 [NOTICE] switch_core_session.c:1577 Session 5558 (sofia/external/0542526278@212.199.157.154:5060) Ended 2015-08-18 07:34:04.056039 [NOTICE] switch_core_session.c:1581 Close Channel sofia/external/0542526278@212.199.157.154:5060 [CS_DESTROY] 2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:566 (sofia/external/0542526278@212.199.157.154:5060) Callstate Change HANGUP -> DOWN 2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:569 (sofia/external/0542526278@212.199.157.154:5060) Running State Change CS_DESTROY 2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:579 (sofia/external/0542526278@212.199.157.154:5060) State DESTROY 2015-08-18 07:34:04.056039 [DEBUG] mod_sofia.c:399 sofia/external/0542526278@212.199.157.154:5060 SOFIA DESTROY 2015-08-18 07:34:04.056039 [DEBUG] switch_rtp.c:948 [ zrtp engine]: STOP STREAM ID=1550 mode=CLEAR state=NOZRTP. 2015-08-18 07:34:04.056039 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <NONE>. 2015-08-18 07:34:04.056039 [DEBUG] switch_rtp.c:948 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE. 2015-08-18 07:34:04.056039 [DEBUG] switch_rtp.c:948 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE. 2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:99 sofia/external/0542526278@212.199.157.154:5060 Standard DESTROY 2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:579 (sofia/external/0542526278@212.199.157.154:5060) State DESTROY going to sleep 2015-08-18 07:34:04.156052 [DEBUG] switch_scheduler.c:144 Deleting task 790 switch_ivr_schedule_hangup (57f517c6-4562-11e5-b0a7-e7d40967f7d3)