------------------------------------------------------------------------
recv 909 bytes from udp/[192.168.100.31]:35060 at 12:46:28.143480:
------------------------------------------------------------------------
INVITE sip:1000@aio.kazoo SIP/2.0
Via: SIP/2.0/UDP 192.168.100.31:35060;rport;branch=z9hG4bK1945324121
From: <sip:athena@aio.kazoo>;tag=1939714079
To: <sip:1000@aio.kazoo>
Call-ID: 828301644
CSeq: 21 INVITE
Contact: <sip:athena@192.168.100.31:35060>
Proxy-Authorization: Digest username="athena", realm="aio.kazoo", nonce="c35dbe94-778b-460f-91f9-48a1ba8255f1", uri="sip:1000@aio.kazoo", response="f0c3a81c5a101794f91e10c9a1807f4c", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000001
Content-Type: application/sdp
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Max-Forwards: 70
User-Agent: Linphone/3.6.1 (eXosip2/3.6.0)
Subject: Phone call
Content-Length: 190
v=0
o=athena 3857 3282 IN IP4 192.168.100.31
s=Talk
c=IN IP4 192.168.100.31
t=0 0
m=audio 13706 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
------------------------------------------------------------------------
2019-01-12 18:54:59.105082 [DEBUG] sofia.c:2522 Re-attaching to session 828301644
2019-01-12 18:54:59.115103 [DEBUG] sofia.c:10092 sofia/sipinterface_1/athena@aio.kazoo receiving invite from 192.168.100.31:35060 version: 1.8.4+git git a0377e9 2018-12-28 07:01:40Z 64bit
2019-01-12 18:54:59.115103 [DEBUG] sofia.c:10218 1 acls to check for proxy
2019-01-12 18:54:59.115103 [DEBUG] sofia.c:10223 checking 192.168.100.31 against acl authoritative
2019-01-12 18:54:59.115103 [DEBUG] sofia.c:10263 IP 192.168.100.31 Rejected by acl "authoritative". Falling back to Digest auth.
2019-01-12 18:54:59.115103 [DEBUG] kazoo_fetch_agent.c:216 Sending directory XML request (62ecc3a4-6332-41b8-acc2-0742fd1c78c2) to ecallmgr@safarov-dell.home <3.1533.0>
2019-01-12 18:54:59.295108 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.1533.0>
2019-01-12 18:54:59.295108 [DEBUG] kazoo_fetch_agent.c:277 Received directory XML (62ecc3a4-6332-41b8-acc2-0742fd1c78c2) after 180ms: <document type="freeswitch/xml"><section name="result" description="Route Not Found"><result status="not found"/></section></document>
2019-01-12 18:54:59.295108 [WARNING] switch_ivr.c:3912 can't find user [athena@aio.kazoo]
2019-01-12 18:54:59.295108 [DEBUG] kazoo_fetch_agent.c:216 Sending directory XML request (5e859c79-d601-436f-ac11-d2341894a8a5) to ecallmgr@safarov-dell.home <3.1533.0>
2019-01-12 18:54:59.495182 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.1533.0>
2019-01-12 18:54:59.495182 [DEBUG] kazoo_fetch_agent.c:277 Received directory XML (5e859c79-d601-436f-ac11-d2341894a8a5) after 200ms: <document type="freeswitch/xml"><section name="directory"><domain name="aio.kazoo"><user id="athena"><variables><variable name="ecallmgr_Username" value="athena"/><variable name="ecallmgr_Realm" value="aio.kazoo"/><variable name="ecallmgr_Account-ID" value="d5acc8dfb902d5c8be326d26cc2c6105"/><variable name="ecallmgr_Authorizing-ID" value="874e670c6e915894e2455e5820e71e61"/><variable name="ecallmgr_Authorizing-Type" value="device"/><variable name="ecallmgr_Owner-ID" value="8b7113aa4080cb37aaf3ef6f8df82f28"/><variable name="ecallmgr_Account-Realm" value="aio.kazoo"/><variable name="ecallmgr_Account-Name" value="master"/><variable name="presence_id" value="1002@aio.kazoo"/><variable name="ecallmgr_Suppress-Unregister-Notifications" value="true"/><variable name="ecallmgr_Register-Overwrite-Notify" value="false"/></variables><params><param name="password" value="athena"/></params></user></domain></section></document>
2019-01-12 18:54:59.495182 [DEBUG] sofia.c:7291 Channel sofia/sipinterface_1/athena@aio.kazoo entering state [received][100]
2019-01-12 18:54:59.495182 [DEBUG] sofia.c:7301 Remote SDP:
v=0
o=athena 3857 3282 IN IP4 192.168.100.31
s=Talk
c=IN IP4 192.168.100.31
t=0 0
m=audio 13706 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
2019-01-12 18:54:59.495182 [DEBUG] sofia.c:7695 (sofia/sipinterface_1/athena@aio.kazoo) State Change CS_NEW -> CS_INIT
2019-01-12 18:54:59.495182 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/athena@aio.kazoo) Running State Change CS_INIT (Cur 1 Tot 238)
2019-01-12 18:54:59.495182 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/athena@aio.kazoo) State INIT
2019-01-12 18:54:59.495182 [DEBUG] mod_sofia.c:93 sofia/sipinterface_1/athena@aio.kazoo SOFIA INIT
2019-01-12 18:54:59.495182 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/athena@aio.kazoo Standard INIT
2019-01-12 18:54:59.495182 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/athena@aio.kazoo) State Change CS_INIT -> CS_ROUTING
2019-01-12 18:54:59.495182 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/athena@aio.kazoo) State INIT going to sleep
2019-01-12 18:54:59.495182 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/athena@aio.kazoo) Running State Change CS_ROUTING (Cur 1 Tot 238)
2019-01-12 18:54:59.495182 [DEBUG] switch_channel.c:2249 (sofia/sipinterface_1/athena@aio.kazoo) Callstate Change DOWN -> RINGING
2019-01-12 18:54:59.495182 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/athena@aio.kazoo) State ROUTING
2019-01-12 18:54:59.495182 [DEBUG] mod_sofia.c:154 sofia/sipinterface_1/athena@aio.kazoo SOFIA ROUTING
2019-01-12 18:54:59.495182 [DEBUG] switch_core_state_machine.c:236 sofia/sipinterface_1/athena@aio.kazoo Standard ROUTING
2019-01-12 18:54:59.495182 [INFO] mod_dialplan_xml.c:637 Processing athena <athena>->1000 in context context_2
send 245 bytes to udp/[192.168.100.31]:35060 at 12:46:28.539378:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.100.31:35060;rport=35060;branch=z9hG4bK1945324121
From: <sip:athena@aio.kazoo>;tag=1939714079
To: <sip:1000@aio.kazoo>
Call-ID: 828301644
CSeq: 21 INVITE
User-Agent: 2600hz
Content-Length: 0
2019-01-12 18:54:59.495182 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 6859
------------------------------------------------------------------------
2019-01-12 18:54:59.495182 [DEBUG] kazoo_fetch_agent.c:216 Sending dialplan XML request (e2ec48ce-f9ea-459a-83b7-b861abed657c) to ecallmgr@safarov-dell.home <3.1492.0>
2019-01-12 18:54:59.695073 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.1492.0>
2019-01-12 18:54:59.695073 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(828301644 ecallmgr_Call-Correlation-ID=63714573013-bb908868)
2019-01-12 18:54:59.695073 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(828301644 ecallmgr_Call-Interaction-ID=63714573013-5b13a7fc)
2019-01-12 18:54:59.695073 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 6923
2019-01-12 18:54:59.695073 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 6923
2019-01-12 18:54:59.705083 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6210.1>
2019-01-12 18:54:59.705083 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6209.1>
2019-01-12 18:54:59.705083 [DEBUG] kazoo_fetch_agent.c:277 Received dialplan XML (e2ec48ce-f9ea-459a-83b7-b861abed657c) after 209ms: <document type="freeswitch/xml"><section name="dialplan" description="Route Park Response"><context name="context_2"><extension name="park"><condition><action application="log" data="NOTICE log|${uuid}|ecallmgr@safarov-dell.home won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=ecallmgr@safarov-dell.home"/><condition field="variable_ecallmgr_Bridge-ID" expression="^$"><action application="export" data="ecallmgr_Bridge-ID=${UUID}" inline="true"/></condition><action application="set" data="ringback=%(2000,4000,440,480)"/><action application="set" data="transfer_ringback=%(2000,4000,440,480)"/><action application="kz_multiset" data="^^|ecallmgr_Username=athena|ecallmgr_Suppress-Unregister-Notifications=true|ecallmgr_Register-Overwrite-Notify=false|ecallmgr_Realm=aio.kazoo|ecallmgr_Owner-ID=8b7113aa4080cb37aaf3ef6f8df82f28|ecallmgr_Fetch-ID=e2ec48ce-f9ea-459a-83b7-b861abed657c|ecallmgr_Caller-Screen-Bit=true|ecallmgr_Caller-Privacy-Hide-Number=false|ecallmgr_Caller-Privacy-Hide-Name=false|ecallmgr_Call-Interaction-ID=63714573013-5b13a7fc|ecallmgr_Call-Correlation-ID=63714573013-bb908868|ecallmgr_Authorizing-Type=device|ecallmgr_Authorizing-ID=874e670c6e915894e2455e5820e71e61|ecallmgr_Account-Realm=aio.kazoo|ecallmgr_Account-Name=master|ecallmgr_Account-ID=d5acc8dfb902d5c8be326d26cc2c6105|ecallmgr_CallFlow-ID=8e59f43782b782e0850668019b150010|ecallmgr_Channel-Authorized=true"/><action application="park"/></condition></extension></context></section></document>
Dialplan: sofia/sipinterface_1/athena@aio.kazoo parsing [context_2->park] continue=false
Dialplan: sofia/sipinterface_1/athena@aio.kazoo Absolute Condition [park]
Dialplan: sofia/sipinterface_1/athena@aio.kazoo Action log(NOTICE log|${uuid}|ecallmgr@safarov-dell.home won call control)
Dialplan: sofia/sipinterface_1/athena@aio.kazoo Action export(ecallmgr_Ecallmgr-Node=ecallmgr@safarov-dell.home)
Dialplan: sofia/sipinterface_1/athena@aio.kazoo Action set(ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/athena@aio.kazoo Action set(transfer_ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/athena@aio.kazoo Action kz_multiset(^^|ecallmgr_Username=athena|ecallmgr_Suppress-Unregister-Notifications=true|ecallmgr_Register-Overwrite-Notify=false|ecallmgr_Realm=aio.kazoo|ecallmgr_Owner-ID=8b7113aa4080cb37aaf3ef6f8df82f28|ecallmgr_Fetch-ID=e2ec48ce-f9ea-459a-83b7-b861abed657c|ecallmgr_Caller-Screen-Bit=true|ecallmgr_Caller-Privacy-Hide-Number=false|ecallmgr_Caller-Privacy-Hide-Name=false|ecallmgr_Call-Interaction-ID=63714573013-5b13a7fc|ecallmgr_Call-Correlation-ID=63714573013-bb908868|ecallmgr_Authorizing-Type=device|ecallmgr_Authorizing-ID=874e670c6e915894e2455e5820e71e61|ecallmgr_Account-Realm=aio.kazoo|ecallmgr_Account-Name=master|ecallmgr_Account-ID=d5acc8dfb902d5c8be326d26cc2c6105|ecallmgr_CallFlow-ID=8e59f43782b782e0850668019b150010|ecallmgr_Channel-Authorized=true)
Dialplan: sofia/sipinterface_1/athena@aio.kazoo Action park()
|--- Dialplan: Processing recursive conditions level:1 [park_recur_1] require-nested=TRUE
|--- Dialplan: sofia/sipinterface_1/athena@aio.kazoo Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
|--- Dialplan: sofia/sipinterface_1/athena@aio.kazoo Action export(ecallmgr_Bridge-ID=${UUID}) INLINE
EXECUTE sofia/sipinterface_1/athena@aio.kazoo export(ecallmgr_Bridge-ID=828301644)
2019-01-12 18:54:59.705083 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Bridge-ID]=[828301644]
2019-01-12 18:54:59.705083 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 7437
2019-01-12 18:54:59.705083 [DEBUG] switch_core_state_machine.c:286 (sofia/sipinterface_1/athena@aio.kazoo) State Change CS_ROUTING -> CS_EXECUTE
2019-01-12 18:54:59.705083 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/athena@aio.kazoo) State ROUTING going to sleep
2019-01-12 18:54:59.705083 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/athena@aio.kazoo) Running State Change CS_EXECUTE (Cur 1 Tot 238)
2019-01-12 18:54:59.705083 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/athena@aio.kazoo) State EXECUTE
2019-01-12 18:54:59.705083 [DEBUG] mod_sofia.c:209 sofia/sipinterface_1/athena@aio.kazoo SOFIA EXECUTE
2019-01-12 18:54:59.705083 [DEBUG] switch_core_state_machine.c:328 sofia/sipinterface_1/athena@aio.kazoo Standard EXECUTE
EXECUTE sofia/sipinterface_1/athena@aio.kazoo log(NOTICE log|828301644|ecallmgr@safarov-dell.home won call control)
2019-01-12 18:54:59.705083 [NOTICE] mod_dptools.c:1792 log|828301644|ecallmgr@safarov-dell.home won call control
2019-01-12 18:54:59.705083 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 7503
EXECUTE sofia/sipinterface_1/athena@aio.kazoo export(ecallmgr_Ecallmgr-Node=ecallmgr@safarov-dell.home)
2019-01-12 18:54:59.715083 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallmgr@safarov-dell.home]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 7571
EXECUTE sofia/sipinterface_1/athena@aio.kazoo set(ringback=%(2000,4000,440,480))
2019-01-12 18:54:59.715083 [DEBUG] mod_dptools.c:1598 SET sofia/sipinterface_1/athena@aio.kazoo [ringback]=[%(2000,4000,440,480)]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 7574
EXECUTE sofia/sipinterface_1/athena@aio.kazoo set(transfer_ringback=%(2000,4000,440,480))
2019-01-12 18:54:59.715083 [DEBUG] mod_dptools.c:1598 SET sofia/sipinterface_1/athena@aio.kazoo [transfer_ringback]=[%(2000,4000,440,480)]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 7575
EXECUTE sofia/sipinterface_1/athena@aio.kazoo kz_multiset(^^|ecallmgr_Username=athena|ecallmgr_Suppress-Unregister-Notifications=true|ecallmgr_Register-Overwrite-Notify=false|ecallmgr_Realm=aio.kazoo|ecallmgr_Owner-ID=8b7113aa4080cb37aaf3ef6f8df82f28|ecallmgr_Fetch-ID=e2ec48ce-f9ea-459a-83b7-b861abed657c|ecallmgr_Caller-Screen-Bit=true|ecallmgr_Caller-Privacy-Hide-Number=false|ecallmgr_Caller-Privacy-Hide-Name=false|ecallmgr_Call-Interaction-ID=63714573013-5b13a7fc|ecallmgr_Call-Correlation-ID=63714573013-bb908868|ecallmgr_Authorizing-Type=device|ecallmgr_Authorizing-ID=874e670c6e915894e2455e5820e71e61|ecallmgr_Account-Realm=aio.kazoo|ecallmgr_Account-Name=master|ecallmgr_Account-ID=d5acc8dfb902d5c8be326d26cc2c6105|ecallmgr_CallFlow-ID=8e59f43782b782e0850668019b150010|ecallmgr_Channel-Authorized=true)
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Username]=[athena]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Suppress-Unregister-Notifications]=[true]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Register-Overwrite-Notify]=[false]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Realm]=[aio.kazoo]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Owner-ID]=[8b7113aa4080cb37aaf3ef6f8df82f28]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Fetch-ID]=[e2ec48ce-f9ea-459a-83b7-b861abed657c]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Caller-Screen-Bit]=[true]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Caller-Privacy-Hide-Number]=[false]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Caller-Privacy-Hide-Name]=[false]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Call-Interaction-ID]=[63714573013-5b13a7fc]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Call-Correlation-ID]=[63714573013-bb908868]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Authorizing-Type]=[device]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Authorizing-ID]=[874e670c6e915894e2455e5820e71e61]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Account-Realm]=[aio.kazoo]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Account-Name]=[master]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Account-ID]=[d5acc8dfb902d5c8be326d26cc2c6105]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_CallFlow-ID]=[8e59f43782b782e0850668019b150010]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [ecallmgr_Channel-Authorized]=[true]
2019-01-12 18:54:59.715083 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8514
2019-01-12 18:54:59.715083 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 9466
EXECUTE sofia/sipinterface_1/athena@aio.kazoo park()
2019-01-12 18:54:59.897377 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6211.1>
2019-01-12 18:54:59.916902 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(828301644 ^^~ecallmgr_Username=athena~ecallmgr_Suppress-Unregister-Notifications=true~ecallmgr_Register-Overwrite-Notify=false~ecallmgr_Realm=aio.kazoo~ecallmgr_Owner-ID=8b7113aa4080cb37aaf3ef6f8df82f28~ecallmgr_Fetch-ID=e2ec48ce-f9ea-459a-83b7-b861abed657c~ecallmgr_Caller-Screen-Bit=true~ecallmgr_Caller-Privacy-Hide-Number=false~ecallmgr_Caller-Privacy-Hide-Name=false~ecallmgr_Call-Interaction-ID=63714573013-5b13a7fc~ecallmgr_Call-Correlation-ID=63714573013-bb908868~ecallmgr_Authorizing-Type=device~ecallmgr_Authorizing-ID=874e670c6e915894e2455e5820e71e61~ecallmgr_Account-Realm=aio.kazoo~ecallmgr_Account-Name=master~ecallmgr_Account-ID=d5acc8dfb902d5c8be326d26cc2c6105~ecallmgr_CallFlow-ID=8e59f43782b782e0850668019b150010~ecallmgr_Channel-Authorized=true~ecallmgr_Application-Node=kazoo_apps@safarov-dell.home~ecallmgr_Application-Name=callflow)
2019-01-12 18:54:59.916902 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 7843
2019-01-12 18:54:59.945064 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6211.1>
2019-01-12 18:54:59.945064 [NOTICE] kazoo_node.c:430 log|828301644|executing kz_multiset ^^~effective_caller_id_name=user athena~effective_caller_id_number=1002
2019-01-12 18:54:59.955280 [DEBUG] switch_ivr.c:625 sofia/sipinterface_1/athena@aio.kazoo Command Execute kz_multiset(^^~effective_caller_id_name=user athena~effective_caller_id_number=1002)
EXECUTE sofia/sipinterface_1/athena@aio.kazoo kz_multiset(^^~effective_caller_id_name=user athena~effective_caller_id_number=1002)
2019-01-12 18:54:59.955280 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [effective_caller_id_name]=[user athena]
2019-01-12 18:54:59.955280 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/athena@aio.kazoo SET [effective_caller_id_number]=[1002]
2019-01-12 18:54:59.955280 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8137
2019-01-12 18:54:59.955280 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8407
2019-01-12 18:55:00.145118 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6227.1>
2019-01-12 18:55:00.155131 [NOTICE] kazoo_node.c:430 log|828301644|executing event Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=3383339d2c53ab77ac7066b7b61ee4cf
2019-01-12 18:55:00.155131 [DEBUG] switch_ivr.c:625 sofia/sipinterface_1/athena@aio.kazoo Command Execute event(Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=3383339d2c53ab77ac7066b7b61ee4cf)
EXECUTE sofia/sipinterface_1/athena@aio.kazoo event(Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=3383339d2c53ab77ac7066b7b61ee4cf)
2019-01-12 18:55:00.165075 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8385
2019-01-12 18:55:00.165075 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8601
2019-01-12 18:55:00.355131 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6227.1>
2019-01-12 18:55:00.355131 [NOTICE] kazoo_node.c:430 log|828301644|executing kz_export ^^~ringback=%(2000,4000,440,480)~transfer_ringback=%(2000,4000,440,480)
2019-01-12 18:55:00.365124 [DEBUG] switch_ivr.c:625 sofia/sipinterface_1/athena@aio.kazoo Command Execute kz_export(^^~ringback=%(2000,4000,440,480)~transfer_ringback=%(2000,4000,440,480))
EXECUTE sofia/sipinterface_1/athena@aio.kazoo kz_export(^^~ringback=%(2000,4000,440,480)~transfer_ringback=%(2000,4000,440,480))
2019-01-12 18:55:00.365124 [DEBUG] kazoo_dptools.c:128 sofia/sipinterface_1/athena@aio.kazoo EXPORT [ringback]=[%(2000,4000,440,480)]
2019-01-12 18:55:00.365124 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ringback]=[%(2000,4000,440,480)]
2019-01-12 18:55:00.365124 [DEBUG] kazoo_dptools.c:128 sofia/sipinterface_1/athena@aio.kazoo EXPORT [transfer_ringback]=[%(2000,4000,440,480)]
2019-01-12 18:55:00.365124 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [transfer_ringback]=[%(2000,4000,440,480)]
2019-01-12 18:55:00.365124 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8430
2019-01-12 18:55:00.555172 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6227.1>
2019-01-12 18:55:00.565084 [DEBUG] kazoo_node.c:1344 increased received message buffer size to 2783
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: set continue_on_fail=true
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: export sip_redirect_context=context_2
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: set hangup_after_bridge=true
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: export ecallmgr_Inception=${ecallmgr_Inception}
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: export ecallmgr_Call-Interaction-ID=${ecallmgr_Call-Interaction-ID}
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: export ecallmgr_Call-Correlation-ID=${ecallmgr_Call-Correlation-ID}
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: export nolocal:sip_h_X-ecallmgr_Call-Correlation-ID=${ecallmgr_Call-Correlation-ID}
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: bridge {call_timeout=20,originate_timeout=20,outbound_redirect_fatal='false',bridge_export_vars='hold_music',local_var_clobber='true'}[^^!ecallmgr_Username='safarov'!ecallmgr_Realm='aio.kazoo'!presence_id='safarov@aio.kazoo'!origination_caller_id_number='1002'!origination_caller_id_name='user athena'!origination_callee_id_number='1000'!origination_callee_id_name='Account Admin'!ignore_completed_elsewhere='false'!leg_timeout='20'!sip_h_X-KAZOO-AOR=sip:safarov@aio.kazoo!sip_h_X-KAZOO-INVITE-FORMAT=contact!execute_on_answer_1=kz_multiset ^^~ecallmgr_Media-Recording-Origin=onnet~ecallmgr_Media-Recording-Endpoint-ID=4e952d9f43a4c2e63a0a566a32029f7a~ecallmgr_Media-Recording-ID=201901-c414db92a84521af7420195ee030c8b2~ecallmgr_Media-Name=1723c046430755acbdfb77795b211907.mp3~ecallmgr_Time-Limit=3600~ecallmgr_Media-Recorder=kz_media_recording~record_sample_rate=16000~record_min_sec=0~recording_follow_attxfer=false~recording_follow_transfer=false~RECORD_SOFTWARE=2600Hz, Inc.'s Kazoo~RECORD_STEREO=true~enable_file_write_buffering=false~RECORD_APPEND=true~playback_terminators=none!execute_on_answer_2=unshift media_recordings,/tmp/1723c046430755acbdfb77795b211907.mp3!execute_on_answer_3=unshift ecallmgr_Media-Names,1723c046430755acbdfb77795b211907.mp3!execute_on_answer_4=unshift ecallmgr_Media-Recordings,201901-c414db92a84521af7420195ee030c8b2!execute_on_answer_5=record_session /tmp/1723c046430755acbdfb77795b211907.mp3!ecallmgr_Authorizing-ID='4e952d9f43a4c2e63a0a566a32029f7a'!ecallmgr_Authorizing-Type='device'!ecallmgr_Owner-ID='7441f3b960a700aa29813191c0145888'!ecallmgr_Account-ID='d5acc8dfb902d5c8be326d26cc2c6105'!sdp_secure_savp_only='false'!sip_invite_domain='aio.kazoo'!absolute_codec_string='^^:PCMU:PCMA:H264'!effective_caller_id_number='1002'!effective_caller_id_name='user athena'!effective_callee_id_number='1000'!effective_callee_id_name='Account Admin']sofia/sipinterface_1/safarov@aio.kazoo;fs_path=sip:192.168.100.31:5060
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: event Event-Name=CUSTOM,Event-Subclass=kazoo::masquerade,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=bridge
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:447 log|828301644|building xferext extension: park
2019-01-12 18:55:00.565084 [NOTICE] kazoo_node.c:450 log|828301644|transfered call to xferext extension
2019-01-12 18:55:00.565084 [DEBUG] switch_channel.c:3171 (sofia/sipinterface_1/athena@aio.kazoo) State Change CS_EXECUTE -> CS_ROUTING
2019-01-12 18:55:00.565084 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/athena@aio.kazoo) State EXECUTE going to sleep
2019-01-12 18:55:00.565084 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/athena@aio.kazoo) Running State Change CS_ROUTING (Cur 1 Tot 238)
2019-01-12 18:55:00.565084 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/athena@aio.kazoo) State ROUTING
2019-01-12 18:55:00.565084 [DEBUG] mod_sofia.c:145 Call appears to be already acknowledged
2019-01-12 18:55:00.565084 [DEBUG] mod_sofia.c:154 sofia/sipinterface_1/athena@aio.kazoo SOFIA ROUTING
2019-01-12 18:55:00.565084 [DEBUG] switch_core_state_machine.c:236 sofia/sipinterface_1/athena@aio.kazoo Standard ROUTING
2019-01-12 18:55:00.565084 [DEBUG] switch_core_state_machine.c:256 (sofia/sipinterface_1/athena@aio.kazoo) State Change CS_ROUTING -> CS_EXECUTE
2019-01-12 18:55:00.565084 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/athena@aio.kazoo) State ROUTING going to sleep
2019-01-12 18:55:00.565084 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/athena@aio.kazoo) Running State Change CS_EXECUTE (Cur 1 Tot 238)
2019-01-12 18:55:00.565084 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/athena@aio.kazoo) State EXECUTE
2019-01-12 18:55:00.565084 [DEBUG] mod_sofia.c:209 sofia/sipinterface_1/athena@aio.kazoo SOFIA EXECUTE
2019-01-12 18:55:00.565084 [DEBUG] switch_core_state_machine.c:328 sofia/sipinterface_1/athena@aio.kazoo Standard EXECUTE
EXECUTE sofia/sipinterface_1/athena@aio.kazoo set(continue_on_fail=true)
2019-01-12 18:55:00.565084 [DEBUG] mod_dptools.c:1598 SET sofia/sipinterface_1/athena@aio.kazoo [continue_on_fail]=[true]
EXECUTE sofia/sipinterface_1/athena@aio.kazoo export(sip_redirect_context=context_2)
2019-01-12 18:55:00.565084 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [sip_redirect_context]=[context_2]
EXECUTE sofia/sipinterface_1/athena@aio.kazoo set(hangup_after_bridge=true)
2019-01-12 18:55:00.565084 [DEBUG] mod_dptools.c:1598 SET sofia/sipinterface_1/athena@aio.kazoo [hangup_after_bridge]=[true]
EXECUTE sofia/sipinterface_1/athena@aio.kazoo export(ecallmgr_Inception=)
2019-01-12 18:55:00.565084 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Inception]=[UNDEF]
2019-01-12 18:55:00.565084 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8259
2019-01-12 18:55:00.585104 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8251
2019-01-12 18:55:00.585104 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8312
2019-01-12 18:55:00.595099 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8413
2019-01-12 18:55:00.595099 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8409
EXECUTE sofia/sipinterface_1/athena@aio.kazoo export(ecallmgr_Call-Interaction-ID=63714573013-5b13a7fc)
2019-01-12 18:55:00.595099 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Call-Interaction-ID]=[63714573013-5b13a7fc]
2019-01-12 18:55:00.595099 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8498
EXECUTE sofia/sipinterface_1/athena@aio.kazoo export(ecallmgr_Call-Correlation-ID=63714573013-bb908868)
2019-01-12 18:55:00.595099 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Call-Correlation-ID]=[63714573013-bb908868]
2019-01-12 18:55:00.595099 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8527
EXECUTE sofia/sipinterface_1/athena@aio.kazoo export(nolocal:sip_h_X-ecallmgr_Call-Correlation-ID=63714573013-bb908868)
2019-01-12 18:55:00.595099 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [sip_h_X-ecallmgr_Call-Correlation-ID]=[63714573013-bb908868]
2019-01-12 18:55:00.595099 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 8689
EXECUTE sofia/sipinterface_1/athena@aio.kazoo bridge({call_timeout=20,originate_timeout=20,outbound_redirect_fatal='false',bridge_export_vars='hold_music',local_var_clobber='true'}[^^!ecallmgr_Username='safarov'!ecallmgr_Realm='aio.kazoo'!presence_id='safarov@aio.kazoo'!origination_caller_id_number='1002'!origination_caller_id_name='user athena'!origination_callee_id_number='1000'!origination_callee_id_name='Account Admin'!ignore_completed_elsewhere='false'!leg_timeout='20'!sip_h_X-KAZOO-AOR=sip:safarov@aio.kazoo!sip_h_X-KAZOO-INVITE-FORMAT=contact!execute_on_answer_1=kz_multiset ^^~ecallmgr_Media-Recording-Origin=onnet~ecallmgr_Media-Recording-Endpoint-ID=4e952d9f43a4c2e63a0a566a32029f7a~ecallmgr_Media-Recording-ID=201901-c414db92a84521af7420195ee030c8b2~ecallmgr_Media-Name=1723c046430755acbdfb77795b211907.mp3~ecallmgr_Time-Limit=3600~ecallmgr_Media-Recorder=kz_media_recording~record_sample_rate=16000~record_min_sec=0~recording_follow_attxfer=false~recording_follow_transfer=false~RECORD_SOFTWARE=2600Hz, Inc.'s Kazoo~RECORD_STEREO=true~enable_file_write_buffering=false~RECORD_APPEND=true~playback_terminators=none!execute_on_answer_2=unshift media_recordings,/tmp/1723c046430755acbdfb77795b211907.mp3!execute_on_answer_3=unshift ecallmgr_Media-Names,1723c046430755acbdfb77795b211907.mp3!execute_on_answer_4=unshift ecallmgr_Media-Recordings,201901-c414db92a84521af7420195ee030c8b2!execute_on_answer_5=record_session /tmp/1723c046430755acbdfb77795b211907.mp3!ecallmgr_Authorizing-ID='4e952d9f43a4c2e63a0a566a32029f7a'!ecallmgr_Authorizing-Type='device'!ecallmgr_Owner-ID='7441f3b960a700aa29813191c0145888'!ecallmgr_Account-ID='d5acc8dfb902d5c8be326d26cc2c6105'!sdp_secure_savp_only='false'!sip_invite_domain='aio.kazoo'!absolute_codec_string='^^:PCMU:PCMA:H264'!effective_caller_id_number='1002'!effective_caller_id_name='user athena'!effective_callee_id_number='1000'!effective_callee_id_name='Account Admin']sofia/sipinterface_1/safarov@aio.kazoo;fs_path=sip:192.168.100.31:5060)
2019-01-12 18:55:00.605087 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/athena@aio.kazoo EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[828301644] to event
2019-01-12 18:55:00.605087 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/athena@aio.kazoo EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallmgr@safarov-dell.home] to event
2019-01-12 18:55:00.605087 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/athena@aio.kazoo EXPORTING[export_vars] [ringback]=[%(2000,4000,440,480)] to event
2019-01-12 18:55:00.605087 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/athena@aio.kazoo EXPORTING[export_vars] [transfer_ringback]=[%(2000,4000,440,480)] to event
2019-01-12 18:55:00.605087 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/athena@aio.kazoo EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event
2019-01-12 18:55:00.605087 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/athena@aio.kazoo EXPORTING[export_vars] [ecallmgr_Call-Interaction-ID]=[63714573013-5b13a7fc] to event
2019-01-12 18:55:00.605087 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/athena@aio.kazoo EXPORTING[export_vars] [ecallmgr_Call-Correlation-ID]=[63714573013-bb908868] to event
2019-01-12 18:55:00.605087 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/athena@aio.kazoo EXPORTING[export_vars] [sip_h_X-ecallmgr_Call-Correlation-ID]=[63714573013-bb908868] to event
2019-01-12 18:55:00.605087 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables
2019-01-12 18:55:00.605087 [DEBUG] switch_ivr_originate.c:2749 Parsing session specific variables
2019-01-12 18:55:00.605087 [NOTICE] switch_channel.c:1104 New Channel sofia/sipinterface_1/safarov@aio.kazoo [e23a17fd-d54c-4ee9-ad45-23d6326faec5]
2019-01-12 18:55:00.605087 [DEBUG] mod_sofia.c:5018 (sofia/sipinterface_1/safarov@aio.kazoo) State Change CS_NEW -> CS_INIT
2019-01-12 18:55:00.605087 [DEBUG] switch_ivr_originate.c:3056 sofia/sipinterface_1/safarov@aio.kazoo Setting leg timeout to 20
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/safarov@aio.kazoo) Running State Change CS_INIT (Cur 2 Tot 239)
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/safarov@aio.kazoo) State INIT
2019-01-12 18:55:00.605087 [DEBUG] mod_sofia.c:93 sofia/sipinterface_1/safarov@aio.kazoo SOFIA INIT
2019-01-12 18:55:00.605087 [DEBUG] sofia_glue.c:1271 sip:192.168.100.31:5060 Setting proxy route to sofia/sipinterface_1/safarov@aio.kazoo
2019-01-12 18:55:00.605087 [DEBUG] sofia_glue.c:1302 sofia/sipinterface_1/safarov@aio.kazoo sending invite version: 1.8.4+git git a0377e9 2018-12-28 07:01:40Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1547287376 1547287377 IN IP4 192.168.100.31
s=FreeSWITCH
c=IN IP4 192.168.100.31
t=0 0
m=audio 31924 RTP/AVP 0 8 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
m=video 19724 RTP/AVP 102
b=AS:1024
a=rtpmap:102 H264/90000
a=sendrecv
a=rtcp-fb:102 ccm fir
a=rtcp-fb:102 ccm tmmbr
a=rtcp-fb:102 nack
a=rtcp-fb:102 nack pli
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/safarov@aio.kazoo Standard INIT
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/safarov@aio.kazoo) State Change CS_INIT -> CS_ROUTING
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/safarov@aio.kazoo) State INIT going to sleep
send 1461 bytes to udp/[192.168.100.31]:5060 at 12:46:29.648161:
------------------------------------------------------------------------
INVITE sip:safarov@aio.kazoo SIP/2.0
Via: SIP/2.0/UDP 192.168.100.31:11000;rport;branch=z9hG4bKj20HUFp5K4a9a
Route: <sip:192.168.100.31:5060>
Max-Forwards: 69
From: "user athena" <sip:1002@aio.kazoo>;tag=r7rK3gtHrDa0D
To: <sip:safarov@aio.kazoo>
Call-ID: e23a17fd-d54c-4ee9-ad45-23d6326faec5
CSeq: 133355730 INVITE
Contact: <sip:mod_sofia@192.168.100.31:11000>
User-Agent: 2600hz
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 427
X-ecallmgr_Call-Correlation-ID: 63714573013-bb908868
X-KAZOO-AOR: sip:safarov@aio.kazoo
X-KAZOO-INVITE-FORMAT: contact
X-FS-Support: update_display,send_info
Remote-Party-ID: "user athena" <sip:1002@aio.kazoo>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1547287376 1547287377 IN IP4 192.168.100.31
s=FreeSWITCH
c=IN IP4 192.168.100.31
t=0 0
m=audio 31924 RTP/AVP 0 8 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
m=video 19724 RTP/AVP 102
b=AS:1024
a=rtpmap:102 H264/90000
a=rtcp-fb:102 ccm fir
a=rtcp-fb:102 ccm tmmbr
a=rtcp-fb:102 nack
a=rtcp-fb:102 nack pli
------------------------------------------------------------------------
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/safarov@aio.kazoo) Running State Change CS_ROUTING (Cur 2 Tot 239)
2019-01-12 18:55:00.605087 [DEBUG] sofia.c:7291 Channel sofia/sipinterface_1/safarov@aio.kazoo entering state [calling][0]
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/safarov@aio.kazoo) State ROUTING
2019-01-12 18:55:00.605087 [DEBUG] mod_sofia.c:154 sofia/sipinterface_1/safarov@aio.kazoo SOFIA ROUTING
2019-01-12 18:55:00.605087 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/safarov@aio.kazoo) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/safarov@aio.kazoo) State ROUTING going to sleep
2019-01-12 18:55:00.605087 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 4343
2019-01-12 18:55:00.605087 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 9337
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/safarov@aio.kazoo) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 239)
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/safarov@aio.kazoo) State CONSUME_MEDIA
2019-01-12 18:55:00.605087 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/safarov@aio.kazoo) State CONSUME_MEDIA going to sleep
recv 329 bytes from udp/[192.168.100.31]:5060 at 12:46:29.653414:
------------------------------------------------------------------------
SIP/2.0 100 Attempting to connect your call
Via: SIP/2.0/UDP 192.168.100.31:11000;rport=11000;branch=z9hG4bKj20HUFp5K4a9a;received=192.168.100.31
From: "user athena" <sip:1002@aio.kazoo>;tag=r7rK3gtHrDa0D
To: <sip:safarov@aio.kazoo>
Call-ID: e23a17fd-d54c-4ee9-ad45-23d6326faec5
CSeq: 133355730 INVITE
Content-Length: 0
------------------------------------------------------------------------
2019-01-12 18:55:00.615085 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6227.1>
2019-01-12 18:55:00.615085 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(e23a17fd-d54c-4ee9-ad45-23d6326faec5 ^^~ecallmgr_Account-ID=d5acc8dfb902d5c8be326d26cc2c6105~ecallmgr_Global-Resource=false~ecallmgr_Channel-Authorized=true)
2019-01-12 18:55:00.636429 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 9501
2019-01-12 18:55:00.665065 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(e23a17fd-d54c-4ee9-ad45-23d6326faec5 ecallmgr_Call-Interaction-ID=63714573013-5b13a7fc)
2019-01-12 18:55:00.665065 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6261.1>
2019-01-12 18:55:00.665065 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 9432
2019-01-12 18:55:00.865158 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6227.1>
recv 449 bytes from udp/[192.168.100.31]:5060 at 12:46:30.310316:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.100.31:11000;received=192.168.100.31;rport=11000;branch=z9hG4bKj20HUFp5K4a9a
From: "user athena" <sip:1002@aio.kazoo>;tag=r7rK3gtHrDa0D
To: <sip:safarov@aio.kazoo>;tag=jTSUwgb
Call-ID: e23a17fd-d54c-4ee9-ad45-23d6326faec5
CSeq: 133355730 INVITE
User-Agent: LinphoneAndroid/4.0.1 (belle-sip/1.6.3)
Supported: replaces, outbound, gruu
Record-route: <sip:192.168.100.31;lr=on;ftag=r7rK3gtHrDa0D>
------------------------------------------------------------------------
2019-01-12 18:55:01.275573 [DEBUG] sofia.c:7291 Channel sofia/sipinterface_1/safarov@aio.kazoo entering state [proceeding][180]
2019-01-12 18:55:01.275573 [NOTICE] sofia.c:7401 Ring-Ready sofia/sipinterface_1/safarov@aio.kazoo!
2019-01-12 18:55:01.275573 [DEBUG] switch_channel.c:3354 (sofia/sipinterface_1/safarov@aio.kazoo) Callstate Change DOWN -> RINGING
2019-01-12 18:55:01.275573 [INFO] switch_ivr_originate.c:1246 Sending early media
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:3781 Set Codec sofia/sipinterface_1/athena@aio.kazoo PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2019-01-12 18:55:01.275573 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/athena@aio.kazoo Original read codec set to PCMA:8
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:5795 sofia/sipinterface_1/athena@aio.kazoo Set 2833 dtmf send payload to 101 recv payload to 101
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:8510 AUDIO RTP [sofia/sipinterface_1/athena@aio.kazoo] 192.168.100.31 port 21624 -> 192.168.100.31 port 13706 codec: 8 ms: 20
2019-01-12 18:55:01.275573 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:8814 sofia/sipinterface_1/athena@aio.kazoo Set 2833 dtmf send payload to 101
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:8821 sofia/sipinterface_1/athena@aio.kazoo Set 2833 dtmf receive payload to 101
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:8844 sofia/sipinterface_1/athena@aio.kazoo Set rtp dtmf delay to 40
2019-01-12 18:55:01.275573 [NOTICE] sofia_media.c:92 Pre-Answer sofia/sipinterface_1/athena@aio.kazoo!
2019-01-12 18:55:01.275573 [DEBUG] switch_channel.c:3482 (sofia/sipinterface_1/athena@aio.kazoo) Callstate Change RINGING -> EARLY
2019-01-12 18:55:01.275573 [DEBUG] switch_core_media.c:8493 Audio params are unchanged for sofia/sipinterface_1/athena@aio.kazoo.
2019-01-12 18:55:01.275573 [DEBUG] mod_sofia.c:2504 Ring SDP:
v=0
o=FreeSWITCH 1547297677 1547297678 IN IP4 192.168.100.31
s=FreeSWITCH
c=IN IP4 192.168.100.31
t=0 0
m=audio 21624 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2019-01-12 18:55:01.275573 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 11822
send 1031 bytes to udp/[192.168.100.31]:35060 at 12:46:30.324801:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.100.31:35060;rport=35060;branch=z9hG4bK1945324121
From: <sip:athena@aio.kazoo>;tag=1939714079
To: <sip:1000@aio.kazoo>;tag=QyZt1N9DU4KDj
Call-ID: 828301644
CSeq: 21 INVITE
Contact: <sip:1000@192.168.100.31:11000;transport=udp>
User-Agent: 2600hz
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 224
Remote-Party-ID: "1000" <sip:1000@aio.kazoo>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1547297677 1547297678 IN IP4 192.168.100.31
s=FreeSWITCH
c=IN IP4 192.168.100.31
t=0 0
m=audio 21624 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2019-01-12 18:55:01.287066 [DEBUG] switch_ivr_originate.c:1304 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2019-01-12 18:55:01.287066 [DEBUG] switch_core_codec.c:223 sofia/sipinterface_1/athena@aio.kazoo Push codec L16:100
2019-01-12 18:55:01.287066 [DEBUG] switch_ivr_originate.c:1373 Play Ringback Tone [%(2000,4000,440,480)]
2019-01-12 18:55:01.305080 [DEBUG] sofia.c:7291 Channel sofia/sipinterface_1/athena@aio.kazoo entering state [early][183]
recv 344 bytes from udp/[192.168.100.31]:5060 at 12:46:30.419286:
------------------------------------------------------------------------
OPTIONS sip:192.168.100.31:11000 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.31;branch=z9hG4bKbe2.ac219651000000000000000000000000.0
To: <sip:192.168.100.31:11000>
From: <sip:sipcheck@safarov-dell.home>;tag=1f6333e227a91274915eae760737b59b-c09b
CSeq: 10 OPTIONS
Call-ID: 196225584a61b06c-84@192.168.100.31
Max-Forwards: 70
Content-Length: 0
------------------------------------------------------------------------
send 708 bytes to udp/[192.168.100.31]:5060 at 12:46:30.419910:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.100.31;branch=z9hG4bKbe2.ac219651000000000000000000000000.0
From: <sip:sipcheck@safarov-dell.home>;tag=1f6333e227a91274915eae760737b59b-c09b
To: <sip:192.168.100.31:11000>;tag=Sgjc5BBNNp0jS
Call-ID: 196225584a61b06c-84@192.168.100.31
CSeq: 10 OPTIONS
Contact: <sip:192.168.100.31:11000>
User-Agent: 2600hz
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
------------------------------------------------------------------------
recv 449 bytes from udp/[192.168.100.31]:5060 at 12:46:30.464118:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.100.31:11000;received=192.168.100.31;rport=11000;branch=z9hG4bKj20HUFp5K4a9a
From: "user athena" <sip:1002@aio.kazoo>;tag=r7rK3gtHrDa0D
To: <sip:safarov@aio.kazoo>;tag=jTSUwgb
Call-ID: e23a17fd-d54c-4ee9-ad45-23d6326faec5
CSeq: 133355730 INVITE
User-Agent: LinphoneAndroid/4.0.1 (belle-sip/1.6.3)
Supported: replaces, outbound, gruu
Record-route: <sip:192.168.100.31;lr=on;ftag=r7rK3gtHrDa0D>
------------------------------------------------------------------------
2019-01-12 18:55:01.415558 [DEBUG] sofia.c:7291 Channel sofia/sipinterface_1/safarov@aio.kazoo entering state [proceeding][180]
2019-01-12 18:55:01.435089 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
recv 897 bytes from udp/[192.168.100.31]:5060 at 12:46:32.573572:
------------------------------------------------------------------------
SIP/2.0 200 Ok
Via: SIP/2.0/UDP 192.168.100.31:11000;received=192.168.100.31;rport=11000;branch=z9hG4bKj20HUFp5K4a9a
From: "user athena" <sip:1002@aio.kazoo>;tag=r7rK3gtHrDa0D
To: <sip:safarov@aio.kazoo>;tag=jTSUwgb
Call-ID: e23a17fd-d54c-4ee9-ad45-23d6326faec5
CSeq: 133355730 INVITE
User-Agent: LinphoneAndroid/4.0.1 (belle-sip/1.6.3)
Supported: replaces, outbound, gruu
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Contact: <sip:safarov@192.168.100.28:46882;gr=urn:uuid:07286db4-6183-40fe-a86c-90af9ba715d8>;+org.linphone.specs=groupchat
Content-Type: application/sdp
Content-Length: 186
Record-route: <sip:192.168.100.31;lr=on;ftag=r7rK3gtHrDa0D>
v=0
o=safarov 3496 3343 IN IP4 192.168.100.28
s=Talk
c=IN IP4 192.168.100.28
t=0 0
m=audio 7076 RTP/AVP 0 8 101
a=rtpmap:101 telephone-event/8000
m=video 0 RTP/AVP 0
a=inactive
------------------------------------------------------------------------
2019-01-12 18:55:03.535418 [DEBUG] sofia.c:7291 Channel sofia/sipinterface_1/safarov@aio.kazoo entering state [completing][200]
2019-01-12 18:55:03.535418 [DEBUG] sofia.c:7301 Remote SDP:
v=0
o=safarov 3496 3343 IN IP4 192.168.100.28
s=Talk
c=IN IP4 192.168.100.28
t=0 0
m=audio 7076 RTP/AVP 0 8 101
a=rtpmap:101 telephone-event/8000
m=video 0 RTP/AVP 0
2019-01-12 18:55:03.535418 [NOTICE] sofia.c:7304 Pre-Answer sofia/sipinterface_1/safarov@aio.kazoo!
2019-01-12 18:55:03.535418 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 11718
2019-01-12 18:55:03.535418 [DEBUG] switch_channel.c:3482 (sofia/sipinterface_1/safarov@aio.kazoo) Callstate Change RINGING -> EARLY
send 477 bytes to udp/[192.168.100.31]:5060 at 12:46:32.579783:
------------------------------------------------------------------------
ACK sip:safarov@192.168.100.28:46882;gr=urn:uuid:07286db4-6183-40fe-a86c-90af9ba715d8 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.31:11000;rport;branch=z9hG4bKKBtaXa78gD1Up
Route: <sip:192.168.100.31;lr=on;ftag=r7rK3gtHrDa0D>
Max-Forwards: 70
From: "user athena" <sip:1002@aio.kazoo>;tag=r7rK3gtHrDa0D
To: <sip:safarov@aio.kazoo>;tag=jTSUwgb
Call-ID: e23a17fd-d54c-4ee9-ad45-23d6326faec5
CSeq: 133355730 ACK
Contact: <sip:mod_sofia@192.168.100.31:11000>
Content-Length: 0
------------------------------------------------------------------------
2019-01-12 18:55:03.535418 [DEBUG] sofia.c:7291 Channel sofia/sipinterface_1/safarov@aio.kazoo entering state [ready][200]
2019-01-12 18:55:03.535418 [DEBUG] switch_core_codec.c:248 sofia/sipinterface_1/athena@aio.kazoo Restore previous codec PCMA:8.
2019-01-12 18:55:03.535418 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/sipinterface_1/safarov@aio.kazoo]
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:3781 Set Codec sofia/sipinterface_1/safarov@aio.kazoo PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2019-01-12 18:55:03.535418 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/safarov@aio.kazoo Original read codec set to PCMU:0
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:5795 sofia/sipinterface_1/safarov@aio.kazoo Set 2833 dtmf send payload to 101 recv payload to 101
2019-01-12 18:55:03.535418 [DEBUG] switch_core_media.c:8510 AUDIO RTP [sofia/sipinterface_1/safarov@aio.kazoo] 192.168.100.31 port 31924 -> 192.168.100.28 port 7076 codec: 0 ms: 20
2019-01-12 18:55:03.535418 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms
2019-01-12 18:55:03.545170 [DEBUG] switch_channel.c:1257 sofia/sipinterface_1/safarov@aio.kazoo EXPORTING[bridge_export_vars] [hold_music]=[local_stream://default] to sofia/sipinterface_1/athena@aio.kazoo
2019-01-12 18:55:03.545170 [DEBUG] switch_channel.c:1257 sofia/sipinterface_1/athena@aio.kazoo EXPORTING[bridge_export_vars] [hold_music]=[local_stream://default] to sofia/sipinterface_1/safarov@aio.kazoo
2019-01-12 18:55:03.545170 [DEBUG] switch_core_media.c:8814 sofia/sipinterface_1/safarov@aio.kazoo Set 2833 dtmf send payload to 101
2019-01-12 18:55:03.545170 [DEBUG] switch_core_media.c:8821 sofia/sipinterface_1/safarov@aio.kazoo Set 2833 dtmf receive payload to 101
2019-01-12 18:55:03.545170 [DEBUG] switch_core_media.c:8844 sofia/sipinterface_1/safarov@aio.kazoo Set rtp dtmf delay to 40
2019-01-12 18:55:03.545170 [NOTICE] sofia.c:8429 Channel [sofia/sipinterface_1/safarov@aio.kazoo] has been answered
2019-01-12 18:55:03.545170 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14194
2019-01-12 18:55:03.545170 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 13117
EXECUTE sofia/sipinterface_1/safarov@aio.kazoo kz_multiset(^^~ecallmgr_Media-Recording-Origin=onnet~ecallmgr_Media-Recording-Endpoint-ID=4e952d9f43a4c2e63a0a566a32029f7a~ecallmgr_Media-Recording-ID=201901-c414db92a84521af7420195ee030c8b2~ecallmgr_Media-Name=1723c046430755acbdfb77795b211907.mp3~ecallmgr_Time-Limit=3600~ecallmgr_Media-Recorder=kz_media_recording~record_sample_rate=16000~record_min_sec=0~recording_follow_attxfer=false~recording_follow_transfer=false~RECORD_SOFTWARE=2600Hz, Inc.s Kazoo~RECORD_STEREO=true~enable_file_write_buffering=false~RECORD_APPEND=true~playback_terminators=none)
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [ecallmgr_Media-Recording-Origin]=[onnet]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [ecallmgr_Media-Recording-Endpoint-ID]=[4e952d9f43a4c2e63a0a566a32029f7a]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [ecallmgr_Media-Recording-ID]=[201901-c414db92a84521af7420195ee030c8b2]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [ecallmgr_Media-Name]=[1723c046430755acbdfb77795b211907.mp3]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [ecallmgr_Time-Limit]=[3600]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [ecallmgr_Media-Recorder]=[kz_media_recording]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [record_sample_rate]=[16000]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [record_min_sec]=[0]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [recording_follow_attxfer]=[false]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [recording_follow_transfer]=[false]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [RECORD_SOFTWARE]=[2600Hz, Inc.s Kazoo]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [RECORD_STEREO]=[true]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [enable_file_write_buffering]=[false]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [RECORD_APPEND]=[true]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/safarov@aio.kazoo SET [playback_terminators]=[none]
EXECUTE sofia/sipinterface_1/safarov@aio.kazoo unshift(media_recordings,/tmp/1723c046430755acbdfb77795b211907.mp3)
2019-01-12 18:55:03.545170 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14497
2019-01-12 18:55:03.545170 [DEBUG] mod_dptools.c:1598 UNSHIFT sofia/sipinterface_1/safarov@aio.kazoo [media_recordings]=[/tmp/1723c046430755acbdfb77795b211907.mp3]
EXECUTE sofia/sipinterface_1/safarov@aio.kazoo unshift(ecallmgr_Media-Names,1723c046430755acbdfb77795b211907.mp3)
2019-01-12 18:55:03.545170 [DEBUG] mod_dptools.c:1598 UNSHIFT sofia/sipinterface_1/safarov@aio.kazoo [ecallmgr_Media-Names]=[1723c046430755acbdfb77795b211907.mp3]
2019-01-12 18:55:03.545170 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 15283
2019-01-12 18:55:03.555141 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14385
EXECUTE sofia/sipinterface_1/safarov@aio.kazoo unshift(ecallmgr_Media-Recordings,201901-c414db92a84521af7420195ee030c8b2)
2019-01-12 18:55:03.555141 [DEBUG] mod_dptools.c:1598 UNSHIFT sofia/sipinterface_1/safarov@aio.kazoo [ecallmgr_Media-Recordings]=[201901-c414db92a84521af7420195ee030c8b2]
2019-01-12 18:55:03.555141 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14460
EXECUTE sofia/sipinterface_1/safarov@aio.kazoo record_session(/tmp/1723c046430755acbdfb77795b211907.mp3)
2019-01-12 18:55:03.565119 [DEBUG] switch_core_file.c:389 File /tmp/1723c046430755acbdfb77795b211907.mp3 sample rate 16000 doesn't match requested rate 8000
2019-01-12 18:55:03.565119 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14561
2019-01-12 18:55:03.578590 [DEBUG] switch_ivr_async.c:1325 Record session sample rate: 8000 -> 16000
2019-01-12 18:55:03.578590 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/sipinterface_1/safarov@aio.kazoo
2019-01-12 18:55:03.578590 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14221
2019-01-12 18:55:03.578590 [DEBUG] switch_channel.c:3781 (sofia/sipinterface_1/safarov@aio.kazoo) Callstate Change EARLY -> ACTIVE
2019-01-12 18:55:03.578590 [DEBUG] switch_ivr_bridge.c:1782 (sofia/sipinterface_1/safarov@aio.kazoo) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2019-01-12 18:55:03.578590 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/safarov@aio.kazoo) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 239)
2019-01-12 18:55:03.578590 [DEBUG] switch_core_state_machine.c:653 (sofia/sipinterface_1/safarov@aio.kazoo) State EXCHANGE_MEDIA
2019-01-12 18:55:03.578590 [DEBUG] mod_sofia.c:645 SOFIA EXCHANGE_MEDIA
2019-01-12 18:55:03.578590 [DEBUG] switch_core_media.c:8493 Audio params are unchanged for sofia/sipinterface_1/athena@aio.kazoo.
2019-01-12 18:55:03.578590 [DEBUG] mod_sofia.c:881 Local SDP sofia/sipinterface_1/athena@aio.kazoo:
v=0
o=FreeSWITCH 1547297677 1547297679 IN IP4 192.168.100.31
s=FreeSWITCH
c=IN IP4 192.168.100.31
t=0 0
m=audio 21624 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
send 1001 bytes to udp/[192.168.100.31]:35060 at 12:46:32.623668:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.100.31:35060;rport=35060;branch=z9hG4bK1945324121
From: <sip:athena@aio.kazoo>;tag=1939714079
To: <sip:1000@aio.kazoo>;tag=QyZt1N9DU4KDj
Call-ID: 828301644
CSeq: 21 INVITE
Contact: <sip:1000@192.168.100.31:11000;transport=udp>
User-Agent: 2600hz
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 224
Remote-Party-ID: "Account Admin" <sip:1000@aio.kazoo>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1547297677 1547297678 IN IP4 192.168.100.31
s=FreeSWITCH
c=IN IP4 192.168.100.31
t=0 0
m=audio 21624 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2019-01-12 18:55:03.578590 [NOTICE] switch_ivr_bridge.c:766 Channel [sofia/sipinterface_1/athena@aio.kazoo] has been answered
2019-01-12 18:55:03.578590 [DEBUG] switch_channel.c:3781 (sofia/sipinterface_1/athena@aio.kazoo) Callstate Change EARLY -> ACTIVE
2019-01-12 18:55:03.578590 [DEBUG] sofia.c:7291 Channel sofia/sipinterface_1/athena@aio.kazoo entering state [completed][200]
2019-01-12 18:55:03.578590 [DEBUG] switch_ivr_async.c:1614 No silence detection configured; assuming start of speech
2019-01-12 18:55:03.578590 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14472
2019-01-12 18:55:03.578590 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 4771
2019-01-12 18:55:03.595715 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14413
2019-01-12 18:55:03.595715 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 4792
2019-01-12 18:55:03.595715 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
recv 616 bytes from udp/[192.168.100.31]:35060 at 12:46:32.639870:
------------------------------------------------------------------------
ACK sip:1000@192.168.100.31:11000;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.100.31:35060;rport;branch=z9hG4bK735379788
From: <sip:athena@aio.kazoo>;tag=1939714079
To: <sip:1000@aio.kazoo>;tag=QyZt1N9DU4KDj
Call-ID: 828301644
CSeq: 21 ACK
Contact: <sip:athena@192.168.100.31:35060>
Proxy-Authorization: Digest username="athena", realm="aio.kazoo", nonce="c35dbe94-778b-460f-91f9-48a1ba8255f1", uri="sip:1000@aio.kazoo", response="f0c3a81c5a101794f91e10c9a1807f4c", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000001
Max-Forwards: 70
User-Agent: Linphone/3.6.1 (eXosip2/3.6.0)
Content-Length: 0
------------------------------------------------------------------------
2019-01-12 18:55:03.615060 [DEBUG] sofia.c:7291 Channel sofia/sipinterface_1/athena@aio.kazoo entering state [ready][200]
2019-01-12 18:55:03.615060 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14544
2019-01-12 18:55:03.638286 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 14751
2019-01-12 18:55:04.125077 [INFO] mod_shout.c:332 LAME 3.99.5 64bits (http://lame.sf.net)
2019-01-12 18:55:04.125077 [INFO] mod_shout.c:332 polyphase lowpass filter disabled
freeswitch@safarov-dell.home>
2019-01-12 18:55:04.515083 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
2019-01-12 18:55:04.515083 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
2019-01-12 18:55:08.035279 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF *:800
2019-01-12 18:55:08.035279 [INFO] switch_channel.c:515 RECV DTMF *:800
2019-01-12 18:55:08.035279 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 4349
2019-01-12 18:55:08.055141 [DEBUG] switch_rtp.c:5424 Send start packet for [*] ts=2112880210 dur=160/160/800 seq=10621 lw=2112880210
2019-01-12 18:55:08.075075 [DEBUG] switch_rtp.c:5323 Send middle packet for [*] ts=2112880210 dur=320/320/800 seq=10622 lw=2112880370
2019-01-12 18:55:08.095066 [DEBUG] switch_rtp.c:5323 Send middle packet for [*] ts=2112880210 dur=480/480/800 seq=10623 lw=2112880530
2019-01-12 18:55:08.115081 [DEBUG] switch_rtp.c:5323 Send middle packet for [*] ts=2112880210 dur=640/640/800 seq=10624 lw=2112880690
2019-01-12 18:55:08.135074 [DEBUG] switch_rtp.c:5323 Send end packet for [*] ts=2112880210 dur=800/800/800 seq=10625 lw=2112880690
2019-01-12 18:55:08.135074 [DEBUG] switch_rtp.c:5323 Send end packet for [*] ts=2112880210 dur=800/800/800 seq=10626 lw=2112880690
2019-01-12 18:55:08.135074 [DEBUG] switch_rtp.c:5323 Send end packet for [*] ts=2112880210 dur=800/800/800 seq=10627 lw=2112880690
2019-01-12 18:55:08.135074 [DEBUG] switch_rtp.c:5271 Queue digit delay of 40ms
2019-01-12 18:55:08.575061 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 2:800
2019-01-12 18:55:08.575061 [INFO] switch_channel.c:515 RECV DTMF 2:800
2019-01-12 18:55:08.575061 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 4349
2019-01-12 18:55:08.595104 [DEBUG] switch_rtp.c:5424 Send start packet for [2] ts=2112884370 dur=160/160/800 seq=10646 lw=2112884370
2019-01-12 18:55:08.615061 [DEBUG] switch_rtp.c:5323 Send middle packet for [2] ts=2112884370 dur=320/320/800 seq=10647 lw=2112884530
2019-01-12 18:55:08.635094 [DEBUG] switch_rtp.c:5323 Send middle packet for [2] ts=2112884370 dur=480/480/800 seq=10648 lw=2112884690
2019-01-12 18:55:08.655061 [DEBUG] switch_rtp.c:5323 Send middle packet for [2] ts=2112884370 dur=640/640/800 seq=10649 lw=2112884850
2019-01-12 18:55:08.675145 [DEBUG] switch_rtp.c:5323 Send end packet for [2] ts=2112884370 dur=800/800/800 seq=10650 lw=2112884850
2019-01-12 18:55:08.675145 [DEBUG] switch_rtp.c:5323 Send end packet for [2] ts=2112884370 dur=800/800/800 seq=10651 lw=2112884850
2019-01-12 18:55:08.675145 [DEBUG] switch_rtp.c:5323 Send end packet for [2] ts=2112884370 dur=800/800/800 seq=10652 lw=2112884850
2019-01-12 18:55:08.675145 [DEBUG] switch_rtp.c:5271 Queue digit delay of 40ms
2019-01-12 18:55:09.385175 [NOTICE] kazoo_node.c:430 log|828301644|executing record_session_mask ${media_recordings[0]}
2019-01-12 18:55:09.395081 [DEBUG] switch_ivr.c:625 sofia/sipinterface_1/athena@aio.kazoo Command Execute record_session_mask(${media_recordings[0]})
EXECUTE sofia/sipinterface_1/athena@aio.kazoo record_session_mask()
2019-01-12 18:55:09.395081 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 12785
2019-01-12 18:55:09.585128 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6227.1>
2019-01-12 18:55:09.585128 [INFO] kazoo_node.c:837 exec: uuid_dump(828301644)
2019-01-12 18:55:09.785194 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6227.1>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
freeswitch@safarov-dell.home>
recv 344 bytes from udp/[192.168.100.31]:5060 at 12:46:40.438476:
------------------------------------------------------------------------
OPTIONS sip:192.168.100.31:11000 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.31;branch=z9hG4bK314.f4d36e32000000000000000000000000.0
To: <sip:192.168.100.31:11000>
From: <sip:sipcheck@safarov-dell.home>;tag=1f6333e227a91274915eae760737b59b-caf5
CSeq: 10 OPTIONS
Call-ID: 196225584a61b070-84@192.168.100.31
Max-Forwards: 70
Content-Length: 0
------------------------------------------------------------------------
send 708 bytes to udp/[192.168.100.31]:5060 at 12:46:40.438843:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.100.31;branch=z9hG4bK314.f4d36e32000000000000000000000000.0
From: <sip:sipcheck@safarov-dell.home>;tag=1f6333e227a91274915eae760737b59b-caf5
To: <sip:192.168.100.31:11000>;tag=tSB566UrjZp5m
Call-ID: 196225584a61b070-84@192.168.100.31
CSeq: 10 OPTIONS
Contact: <sip:192.168.100.31:11000>
User-Agent: 2600hz
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
------------------------------------------------------------------------
2019-01-12 18:55:13.615113 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF *:800
2019-01-12 18:55:13.615113 [INFO] switch_channel.c:515 RECV DTMF *:800
2019-01-12 18:55:13.615113 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 4349
2019-01-12 18:55:13.635067 [DEBUG] switch_rtp.c:5424 Send start packet for [*] ts=2112923410 dur=160/160/800 seq=10876 lw=2112923410
2019-01-12 18:55:13.655108 [DEBUG] switch_rtp.c:5323 Send middle packet for [*] ts=2112923410 dur=320/320/800 seq=10877 lw=2112923570
2019-01-12 18:55:13.675070 [DEBUG] switch_rtp.c:5323 Send middle packet for [*] ts=2112923410 dur=480/480/800 seq=10878 lw=2112923730
2019-01-12 18:55:13.695080 [DEBUG] switch_rtp.c:5323 Send middle packet for [*] ts=2112923410 dur=640/640/800 seq=10879 lw=2112923890
2019-01-12 18:55:13.715086 [DEBUG] switch_rtp.c:5323 Send end packet for [*] ts=2112923410 dur=800/800/800 seq=10880 lw=2112923890
2019-01-12 18:55:13.715086 [DEBUG] switch_rtp.c:5323 Send end packet for [*] ts=2112923410 dur=800/800/800 seq=10881 lw=2112923890
2019-01-12 18:55:13.715086 [DEBUG] switch_rtp.c:5323 Send end packet for [*] ts=2112923410 dur=800/800/800 seq=10882 lw=2112923890
2019-01-12 18:55:13.715086 [DEBUG] switch_rtp.c:5271 Queue digit delay of 40ms
2019-01-12 18:55:14.075183 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 3:800
2019-01-12 18:55:14.075183 [INFO] switch_channel.c:515 RECV DTMF 3:800
2019-01-12 18:55:14.085103 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 4349
2019-01-12 18:55:14.095084 [DEBUG] switch_rtp.c:5424 Send start packet for [3] ts=2112926930 dur=160/160/800 seq=10901 lw=2112926930
2019-01-12 18:55:14.115101 [DEBUG] switch_rtp.c:5323 Send middle packet for [3] ts=2112926930 dur=320/320/800 seq=10902 lw=2112927090
2019-01-12 18:55:14.135091 [DEBUG] switch_rtp.c:5323 Send middle packet for [3] ts=2112926930 dur=480/480/800 seq=10903 lw=2112927250
2019-01-12 18:55:14.155576 [DEBUG] switch_rtp.c:5323 Send middle packet for [3] ts=2112926930 dur=640/640/800 seq=10904 lw=2112927410
2019-01-12 18:55:14.175106 [DEBUG] switch_rtp.c:5323 Send end packet for [3] ts=2112926930 dur=800/800/800 seq=10905 lw=2112927410
2019-01-12 18:55:14.175106 [DEBUG] switch_rtp.c:5323 Send end packet for [3] ts=2112926930 dur=800/800/800 seq=10906 lw=2112927410
2019-01-12 18:55:14.175106 [DEBUG] switch_rtp.c:5323 Send end packet for [3] ts=2112926930 dur=800/800/800 seq=10907 lw=2112927410
2019-01-12 18:55:14.175106 [DEBUG] switch_rtp.c:5271 Queue digit delay of 40ms
freeswitch@safarov-dell.home>
2019-01-12 18:55:14.885099 [NOTICE] kazoo_node.c:430 log|828301644|executing record_session_unmask ${media_recordings[0]}
2019-01-12 18:55:14.895888 [DEBUG] switch_ivr.c:625 sofia/sipinterface_1/athena@aio.kazoo Command Execute record_session_unmask(${media_recordings[0]})
EXECUTE sofia/sipinterface_1/athena@aio.kazoo record_session_unmask()
2019-01-12 18:55:14.895888 [DEBUG] kazoo_event_stream.c:244 increased event stream buffer size to 12789
2019-01-12 18:55:15.085104 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@safarov-dell.home <3.6227.1>
freeswitch@safarov-dell.home>