------------------------------------------------------------------------ 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: ;tag=1939714079 To: Call-ID: 828301644 CSeq: 21 INVITE Contact: 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:
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:
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 ->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: ;tag=1939714079 To: 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:
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: Max-Forwards: 69 From: "user athena" ;tag=r7rK3gtHrDa0D To: Call-ID: e23a17fd-d54c-4ee9-ad45-23d6326faec5 CSeq: 133355730 INVITE Contact: 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" ;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" ;tag=r7rK3gtHrDa0D To: 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" ;tag=r7rK3gtHrDa0D To: ;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: ------------------------------------------------------------------------ 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: ;tag=1939714079 To: ;tag=QyZt1N9DU4KDj Call-ID: 828301644 CSeq: 21 INVITE Contact: 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" ;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: From: ;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: ;tag=1f6333e227a91274915eae760737b59b-c09b To: ;tag=Sgjc5BBNNp0jS Call-ID: 196225584a61b06c-84@192.168.100.31 CSeq: 10 OPTIONS Contact: 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" ;tag=r7rK3gtHrDa0D To: ;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: ------------------------------------------------------------------------ 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" ;tag=r7rK3gtHrDa0D To: ;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: ;+org.linphone.specs=groupchat Content-Type: application/sdp Content-Length: 186 Record-route: 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: Max-Forwards: 70 From: "user athena" ;tag=r7rK3gtHrDa0D To: ;tag=jTSUwgb Call-ID: e23a17fd-d54c-4ee9-ad45-23d6326faec5 CSeq: 133355730 ACK Contact: 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: ;tag=1939714079 To: ;tag=QyZt1N9DU4KDj Call-ID: 828301644 CSeq: 21 INVITE Contact: 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" ;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: ;tag=1939714079 To: ;tag=QyZt1N9DU4KDj Call-ID: 828301644 CSeq: 21 ACK Contact: 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: From: ;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: ;tag=1f6333e227a91274915eae760737b59b-caf5 To: ;tag=tSB566UrjZp5m Call-ID: 196225584a61b070-84@192.168.100.31 CSeq: 10 OPTIONS Contact: 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>