[Freeswitch-users] Freeswitch-Acrobits/iPhone-ZRTP error
Assaf Dahary
adahary at gmail.com
Tue Aug 18 10:22:29 MSD 2015
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 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:33:58.946068 [DEBUG] switch_core_session.c:1016 Send signal
sofia/external/0542526278 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:415
(sofia/external/0542526278 at 212.199.157.154:5060) Running State Change CS_NEW
2015-08-18 07:33:58.946068 [DEBUG] sofia.c:7877
sofia/external/0542526278 at 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 at 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 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:434
(sofia/external/0542526278 at 212.199.157.154:5060) State NEW
2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:415
(sofia/external/0542526278 at 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 at 212.199.157.154:5060) State INIT
2015-08-18 07:33:58.946068 [DEBUG] mod_sofia.c:87
sofia/external/0542526278 at 212.199.157.154:5060 SOFIA INIT
2015-08-18 07:33:58.946068 [DEBUG] mod_sofia.c:127
(sofia/external/0542526278 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:455
(sofia/external/0542526278 at 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 at 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 at 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 at 212.199.157.154:5060) State ROUTING
2015-08-18 07:33:58.946068 [DEBUG] mod_sofia.c:150
sofia/external/0542526278 at 212.199.157.154:5060 SOFIA ROUTING
2015-08-18 07:33:58.946068 [DEBUG] switch_core_state_machine.c:117
sofia/external/0542526278 at 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 at 212.199.157.154:5060 parsing
[external->call_to_99556678] continue=false
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Regex (PASS)
[call_to_99556678] destination_number(722157185) =~ /^722157185$/
break=on-false
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(call_timeout=45)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(ringback=${us-ring})
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(instant_ringback=true)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(x_dst_tariff=)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(x_dialplan_mode=PLIVO-FS)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(x_account_id=0)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(effective_caller_id_number=0542526278)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(effective_caller_id_name=)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(zrtp_secure_media=true)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(zrtp_enrollment=true)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(x_call_type=PSTN2SIP)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(x_user_name=99556678)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(x_domain_name=confidentialtele.com)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(proxy_media=false)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(execute_on_answer=sched_hangup +3600 alloted_timeout)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(hangup_after_bridge=true)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
set(continue_on_fail=true)
Dialplan: sofia/external/0542526278 at 212.199.157.154:5060 Action
bridge(user/99556678 at confidentialtele.com)
2015-08-18 07:33:58.986050 [DEBUG] switch_core_state_machine.c:167
(sofia/external/0542526278 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:33:58.986050 [DEBUG] switch_core_state_machine.c:471
(sofia/external/0542526278 at 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 at 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 at 212.199.157.154:5060) State EXECUTE
2015-08-18 07:33:58.986050 [DEBUG] mod_sofia.c:243
sofia/external/0542526278 at 212.199.157.154:5060 SOFIA EXECUTE
2015-08-18 07:33:58.986050 [DEBUG] switch_core_state_machine.c:209
sofia/external/0542526278 at 212.199.157.154:5060 Standard EXECUTE
EXECUTE sofia/external/0542526278 at 212.199.157.154:5060 set(call_timeout=45)
2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402
sofia/external/0542526278 at 212.199.157.154:5060 SET [call_timeout]=[45]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET
[ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/external/0542526278 at 212.199.157.154:5060
set(instant_ringback=true)
2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402
sofia/external/0542526278 at 212.199.157.154:5060 SET [instant_ringback]=[true]
EXECUTE sofia/external/0542526278 at 212.199.157.154:5060 set(x_dst_tariff=)
2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402
sofia/external/0542526278 at 212.199.157.154:5060 SET [x_dst_tariff]=[UNDEF]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET
[x_dialplan_mode]=[PLIVO-FS]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET [x_account_id]=[0]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET
[effective_caller_id_number]=[0542526278]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET
[effective_caller_id_name]=[UNDEF]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET
[zrtp_secure_media]=[true]
EXECUTE sofia/external/0542526278 at 212.199.157.154:5060
set(zrtp_enrollment=true)
2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402
sofia/external/0542526278 at 212.199.157.154:5060 SET [zrtp_enrollment]=[true]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET [x_call_type]=[PSTN2SIP]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET [x_user_name]=[99556678]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET
[x_domain_name]=[confidentialtele.com]
EXECUTE sofia/external/0542526278 at 212.199.157.154:5060
set(proxy_media=false)
2015-08-18 07:33:58.986050 [DEBUG] mod_dptools.c:1402
sofia/external/0542526278 at 212.199.157.154:5060 SET [proxy_media]=[false]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET
[execute_on_answer]=[sched_hangup +3600 alloted_timeout]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET
[hangup_after_bridge]=[true]
EXECUTE sofia/external/0542526278 at 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 at 212.199.157.154:5060 SET [continue_on_fail]=[true]
EXECUTE sofia/external/0542526278 at 212.199.157.154:5060
bridge(user/99556678 at 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 at confidentialtele.com]
2015-08-18 07:33:59.017997 [NOTICE] switch_channel.c:1050 New Channel
sofia/agents/sip:99556678 at 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 at 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 at 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 at 8000h@20i at 64000b'
2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:415
(sofia/agents/sip:99556678 at 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 at 164.138.115.183:50214) State INIT
2015-08-18 07:33:59.017997 [DEBUG] mod_sofia.c:87
sofia/agents/sip:99556678 at 164.138.115.183:50214 SOFIA INIT
2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:2716
sip:99556678 at 164.138.115.183:50214;rinstance=1E740845;transport=tls Setting
proxy route to sofia/agents/sip:99556678 at 164.138.115.183:50214
2015-08-18 07:33:59.017997 [DEBUG] sofia_glue.c:2744
sofia/agents/sip:99556678 at 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 at 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 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:455
(sofia/agents/sip:99556678 at 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 at 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 at 164.138.115.183:50214) State ROUTING
2015-08-18 07:33:59.017997 [DEBUG] mod_sofia.c:150
sofia/agents/sip:99556678 at 164.138.115.183:50214 SOFIA ROUTING
2015-08-18 07:33:59.017997 [DEBUG] switch_ivr_originate.c:67
(sofia/agents/sip:99556678 at 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 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:33:59.017997 [DEBUG] switch_core_state_machine.c:471
(sofia/agents/sip:99556678 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 212.199.157.154:5060!
2015-08-18 07:33:59.017997 [DEBUG] switch_channel.c:3368
(sofia/external/0542526278 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:33:59.017997 [DEBUG] switch_ivr_originate.c:1248 Raw Codec
Activation Success L16 at 8000hz 1 channel 20ms
2015-08-18 07:33:59.017997 [DEBUG] switch_core_codec.c:219
sofia/external/0542526278 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:33:59.056050 [DEBUG] sofia.c:5815 Channel
sofia/external/0542526278 at 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 at 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 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:33:59.126047 [DEBUG] sofia.c:5815 Channel
sofia/agents/sip:99556678 at 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 at 164.138.115.183:50214!
2015-08-18 07:33:59.126047 [DEBUG] switch_channel.c:3242
(sofia/agents/sip:99556678 at 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 at 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 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:34:02.636038 [DEBUG] sofia.c:5815 Channel
sofia/agents/sip:99556678 at 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 at 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 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:34:02.636038 [DEBUG] sofia.c:5815 Channel
sofia/agents/sip:99556678 at 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 at 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 at 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 at 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 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:02.646130 [NOTICE] sofia.c:6604 Channel
[sofia/agents/sip:99556678 at 164.138.115.183:50214] has been answered
2015-08-18 07:34:02.646130 [DEBUG] switch_channel.c:3647
(sofia/agents/sip:99556678 at 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 at 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 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:02.656044 [NOTICE] switch_ivr_originate.c:3456 Channel
[sofia/external/0542526278 at 212.199.157.154:5060] has been answered
EXECUTE sofia/external/0542526278 at 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 at 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 at 164.138.115.183:50214]
2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:1016 Send signal
sofia/external/0542526278 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:02.656044 [DEBUG] sofia.c:5815 Channel
sofia/external/0542526278 at 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 at 164.138.115.183:50214]
2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:871 Send signal
sofia/agents/sip:99556678 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:871 Send signal
sofia/external/0542526278 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:02.656044 [DEBUG] switch_ivr_bridge.c:1446
(sofia/agents/sip:99556678 at 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 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:34:02.656044 [DEBUG] switch_core_state_machine.c:415
(sofia/agents/sip:99556678 at 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 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:1016 Send signal
sofia/external/0542526278 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:02.656044 [DEBUG] switch_core_session.c:1016 Send signal
sofia/external/0542526278 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:02.696047 [DEBUG] sofia.c:5815 Channel
sofia/external/0542526278 at 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 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:34:02.696047 [DEBUG] switch_core_session.c:933 Send signal
sofia/external/0542526278 at 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 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:34:03.976040 [NOTICE] sofia.c:737 Hangup
sofia/agents/sip:99556678 at 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 at 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 at 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 at 164.138.115.183:50214]
2015-08-18 07:34:03.976040 [DEBUG] switch_ivr_bridge.c:675 Send signal
sofia/external/0542526278 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:481
(sofia/agents/sip:99556678 at 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 at 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 at 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 at 164.138.115.183:50214) State HANGUP
2015-08-18 07:34:03.976040 [DEBUG] mod_sofia.c:506 Channel
sofia/agents/sip:99556678 at 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 at 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 at 212.199.157.154:5060]
2015-08-18 07:34:03.976040 [DEBUG] switch_ivr_bridge.c:675 Send signal
sofia/agents/sip:99556678 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:34:03.976040 [DEBUG] switch_ivr_bridge.c:1544
sofia/agents/sip:99556678 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:48
sofia/agents/sip:99556678 at 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 at 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 at 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 at 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 at 164.138.115.183:50214 [BREAK]
2015-08-18 07:34:03.976040 [DEBUG] switch_channel.c:3187 Send signal
sofia/external/0542526278 at 212.199.157.154:5060 [KILL]
2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:415
(sofia/agents/sip:99556678 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:764
(sofia/agents/sip:99556678 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 164.138.115.183:50214 [CS_DESTROY]
2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:680
(sofia/external/0542526278 at 212.199.157.154:5060) State HANGUP
2015-08-18 07:34:03.976040 [DEBUG] mod_sofia.c:500
sofia/external/0542526278 at 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 at 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 at 212.199.157.154:5060
2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:48
sofia/external/0542526278 at 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 at 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 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:03.976040 [DEBUG] switch_core_state_machine.c:415
(sofia/external/0542526278 at 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 at 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 at 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 at 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 at 164.138.115.183:50214) State DESTROY
2015-08-18 07:34:03.976040 [DEBUG] mod_sofia.c:399
sofia/agents/sip:99556678 at 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 at 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 at 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 at 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 at 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 at 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 at 212.199.157.154:5060 [BREAK]
2015-08-18 07:34:04.056039 [DEBUG] switch_core_session.c:1559 Session 5558
(sofia/external/0542526278 at 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 at 212.199.157.154:5060) Ended
2015-08-18 07:34:04.056039 [NOTICE] switch_core_session.c:1581 Close Channel
sofia/external/0542526278 at 212.199.157.154:5060 [CS_DESTROY]
2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:566
(sofia/external/0542526278 at 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 at 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 at 212.199.157.154:5060) State DESTROY
2015-08-18 07:34:04.056039 [DEBUG] mod_sofia.c:399
sofia/external/0542526278 at 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 at 212.199.157.154:5060 Standard DESTROY
2015-08-18 07:34:04.056039 [DEBUG] switch_core_state_machine.c:579
(sofia/external/0542526278 at 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)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150818/c95c33f6/attachment-0001.html
Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users
mailing list