jlhughes Posted October 30, 2017 Report Posted October 30, 2017 (edited) Howdy, I am getting issues when using Call.Center's proxy feature. It seems that when initiating a transfer, FreeSwitch actually drops the call: ------------------------------------------------------------------------ recv 1275 bytes from udp/[IP]:5060 at 03:18:00.824837: ------------------------------------------------------------------------ REFER sip:888100@IP:11000;transport=udp SIP/2.0 Via: SIP/2.0/UDP IP;branch=z9hG4bK308a.85142f451c1c8d5f32ce0ed159a50c8d.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKVCW.QaXp;rport=6050 From: <sip:user_vrf59sfv4q@DNSName.Com>;tag=49F1CE0E-59F699DF000B94A8-C1A13700 To: <sip:888100@DNSName.Com>;tag=ySv3v1KtepjeD CSeq: 11 REFER Call-ID: 189C155E-59F699DF000B94AC-C1A13700 Max-Forwards: 50 Refer-To: <sip:888701@DNSName.Com?Replaces=4F519138-59F699CD000AA801-C2019700%3Bfrom-tag%3DyEUGDIGcovzut28rIFIK7dtxnFTCzffj%3Bto-tag%3D1B1DA70C-59F699CD000AA7FC-C2019700&Require=replaces> Referred-By: <sip:user_vrf59sfv4q@DNSName.Com>;transport=tcp User-Agent: call.center proxy Contact: <sip:46.19.210.33:6050;transport=udp> Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 X-ecallmgr_Account-ID: 75c5b9a0047e65399de45f41258e38e4 X-ecallmgr_Authorizing-Type: device X-ecallmgr_Authorizing-ID: b2c525170e891ce12950790e47b5eb9f X-ecallmgr_Username: user_vrf59sfv4q X-ecallmgr_Realm: DNSName.Com X-ecallmgr_Account-Realm: DNSName.Com X-ecallmgr_Account-Name: Dove Gospel - Global X-ecallmgr_Presence-ID: 888701@DNSName.Com X-ecallmgr_Owner-ID: 9333eab27c60732f233e2b803e7c073b ------------------------------------------------------------------------ send 430 bytes to udp/[IP]:5060 at 03:18:00.825072: ------------------------------------------------------------------------ SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP IP;branch=z9hG4bK308a.85142f451c1c8d5f32ce0ed159a50c8d.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKVCW.QaXp;rport=6050 From: <sip:user_vrf59sfv4q@DNSName.Com>;tag=49F1CE0E-59F699DF000B94A8-C1A13700 To: <sip:888100@DNSName.Com>;tag=ySv3v1KtepjeD Call-ID: 189C155E-59F699DF000B94AC-C1A13700 CSeq: 11 REFER Content-Length: 0 ------------------------------------------------------------------------ 2017-10-30 03:18:00.825258 [NOTICE] sofia.c:1012 Hangup sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com [CS_EXECUTE] [NORMAL_CLEARING] 2017-10-30 03:18:00.825258 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/kazoo-freeswitch/sounds/http_cache/1f/96a536-bd0e-11e7-a8c9-cf451ddd7335.wav send 566 bytes to udp/[IP]:5060 at 03:18:00.827746: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP IP;branch=z9hG4bK008a.4b19afb713213e3efb1a3216141f829a.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bK1.E6raeQ;rport=6050 From: <sip:user_vrf59sfv4q@DNSName.Com>;tag=49F1CE0E-59F699DF000B94A8-C1A13700 To: <sip:888100@DNSName.Com>;tag=ySv3v1KtepjeD Call-ID: 189C155E-59F699DF000B94AC-C1A13700 CSeq: 12 BYE User-Agent: 2600hz Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2017-10-30 03:18:00.825258 [DEBUG] switch_core_session.c:2815 sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-10-30 03:18:00.825258 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4859 2017-10-30 03:18:00.825258 [DEBUG] switch_core_session.c:2815 sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) State EXECUTE going to sleep 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) Running State Change CS_HANGUP (Cur 3 Tot 369) 2017-10-30 03:18:00.825258 [DEBUG] switch_ivr.c:666 sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com skip receive message [AUDIO_SYNC] (channel is hungup already) 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:850 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) Callstate Change ACTIVE -> HANGUP 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) State HANGUP 2017-10-30 03:18:00.825258 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com hanging up, cause: NORMAL_CLEARING 2017-10-30 03:18:00.825258 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4740 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com Standard HANGUP, cause: NORMAL_CLEARING 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) State HANGUP going to sleep 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:619 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) State Change CS_HANGUP -> CS_REPORTING 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) Running State Change CS_REPORTING (Cur 3 Tot 369) 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) State REPORTING 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:174 sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com Standard REPORTING, cause: NORMAL_CLEARING 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) State REPORTING going to sleep 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:610 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) State Change CS_REPORTING -> CS_DESTROY 2017-10-30 03:18:00.825258 [DEBUG] switch_core_session.c:1665 Session 369 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) Locked, Waiting on external entities 2017-10-30 03:18:00.825258 [NOTICE] switch_core_session.c:1683 Session 369 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) Ended 2017-10-30 03:18:00.825258 [NOTICE] switch_core_session.c:1687 Close Channel sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com [CS_DESTROY] 2017-10-30 03:18:00.825258 [NOTICE] kazoo_node.c:430 log|189C155E-59F699DF000B94AC-C1A13700|executing event Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=b27907d718d7440bbc16bffd946921cd 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:741 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) Running State Change CS_DESTROY (Cur 2 Tot 369) 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) State DESTROY 2017-10-30 03:18:00.825258 [DEBUG] mod_sofia.c:343 sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com SOFIA DESTROY 2017-10-30 03:18:00.825258 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2017-10-30 03:18:00.825258 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2017-10-30 03:18:00.825258 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2017-10-30 03:18:00.825258 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[412] Bytes encoded[43377] Encoded length ms[8240] Average encoded bitrate bps[43377] 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:181 sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com Standard DESTROY 2017-10-30 03:18:00.825258 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_vrf59sfv4q@DNSName.Com) State DESTROY going to sleep 2017-10-30 03:18:00.825258 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4962 2017-10-30 03:18:01.025167 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.8478.23> recv 549 bytes from udp/[IP]:5060 at 03:18:01.165717: ------------------------------------------------------------------------ BYE sip:mod_sofia@IP:11000 SIP/2.0 Via: SIP/2.0/UDP IP;branch=z9hG4bK9381.2a6afc9075123d2c806c07b2945638f4.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bK7ia59aQS;rport=6050 From: <sip:user_vrf59sfv4q@DNSName.Com>;tag=2EA6A39D-59F699CD000A94CC-96C97700 To: "James Hughes" <sip:888701@DNSName.Com>;tag=tNQ0NNgctjS3e CSeq: 10 BYE Call-ID: df05075c-bd20-11e7-a9fd-cf451ddd7335 Max-Forwards: 50 User-Agent: call.center proxy Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 I have tried adding 46.19.210.33 to SBC but this was not successful, and it seems the highlighted issue has been "Internal Server Error". Could you advise a possible solution? Cheers, James Edited October 30, 2017 by jlhughes (see edit history) Quote
Administrators Darren Schreiber Posted November 1, 2017 Administrators Report Posted November 1, 2017 What is call.center Proxy? I have never seen such a user agent before. Can you post the full log from start to finish? Quote
jlhughes Posted November 1, 2017 Author Report Posted November 1, 2017 Hey Darren, Call.Center proxy is a feature that enables a SIP account to be handled by Call Center's push feature, it essentially allows calls to be routed through to iPhones and locations where they block the generic SIP port 5060. It is very useful in the areas we have actually deployed 2600hz. recv 1376 bytes from udp/[KAZOOIP]:5060 at 04:33:09.298513: ------------------------------------------------------------------------ INVITE sip:888701@pbxdg.domain.net:5060;transport=udp SIP/2.0 Record-Route: <sip:KAZOOIP;lr=on;ftag=309022BA-59F94E850003A17D-C1C15700> Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bKfd1a.37859ae0b746929f182e0e4ec2f7fe79.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKpOioMaK2;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=309022BA-59F94E850003A17D-C1C15700 To: <sip:888701@pbxdg.domain.net> CSeq: 10 INVITE Call-ID: 371868A9-59F94E850003A182-C1C15700 Max-Forwards: 50 User-Agent: call.center proxy Content-Type: application/sdp Contact: <sip:46.19.210.33:6050;transport=udp> Content-Length: 261 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 X-ecallmgr_Account-ID: 75c5b9a0047e65399de45f41258e38e4 X-ecallmgr_Authorizing-Type: device X-ecallmgr_Authorizing-ID: c04a2812eff90b41dd1282c4ffc03998 X-ecallmgr_Username: user_f84u8dn62s X-ecallmgr_Realm: pbxdg.domain.net X-ecallmgr_Account-Realm: pbxdg.domain.net X-ecallmgr_Account-Name: Dove Gospel - Global X-ecallmgr_Presence-ID: 888701@pbxdg.domain.net X-ecallmgr_Owner-ID: 9333eab27c60732f233e2b803e7c073b v=0 o=sems 838687344 1399990445 IN IP4 46.19.210.33 s=sems c=IN IP4 46.19.210.33 t=0 0 m=audio 21162 RTP/AVP 120 8 0 96 a=rtpmap:120 opus/48000/2 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=sendrecv a=direction:both ------------------------------------------------------------------------ send 498 bytes to udp/[KAZOOIP]:5060 at 04:33:09.299008: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bKfd1a.37859ae0b746929f182e0e4ec2f7fe79.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKpOioMaK2;rport=6050 Record-Route: <sip:KAZOOIP;lr=on;ftag=309022BA-59F94E850003A17D-C1C15700> From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=309022BA-59F94E850003A17D-C1C15700 To: <sip:888701@pbxdg.domain.net> Call-ID: 371868A9-59F94E850003A182-C1C15700 CSeq: 10 INVITE User-Agent: 2600hz Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:09.295171 [NOTICE] switch_channel.c:1104 New Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [371868A9-59F94E850003A182-C1C15700] 2017-11-01 04:33:09.295171 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_NEW (Cur 1 Tot 485) 2017-11-01 04:33:09.295171 [DEBUG] sofia.c:9873 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net receiving invite from KAZOOIP:5060 version: 1.6.19 64bit 2017-11-01 04:33:09.295171 [DEBUG] sofia.c:9999 1 acls to check for proxy 2017-11-01 04:33:09.295171 [DEBUG] sofia.c:10004 checking KAZOOIP against acl authoritative 2017-11-01 04:33:09.295171 [INFO] sofia.c:10006 KAZOOIP is a proxy according to the authoritative acl 2017-11-01 04:33:09.295171 [DEBUG] sofia.c:10016 network ip is a proxy 2017-11-01 04:33:09.295171 [DEBUG] sofia.c:10020 found auth ip [X-AUTH-IP] header of [46.19.210.33] 2017-11-01 04:33:09.295171 [DEBUG] sofia.c:10044 IP KAZOOIP Rejected by acl "trusted". Falling back to Digest auth. 2017-11-01 04:33:09.295171 [DEBUG] kazoo_fetch_agent.c:216 Sending directory XML request (c350322c-bebd-11e7-b230-cf451ddd7335) to ecallmgr@pbx01.exch1.net <1.1432.0> 2017-11-01 04:33:09.355383 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.1432.0> 2017-11-01 04:33:09.355383 [DEBUG] kazoo_fetch_agent.c:277 Received directory XML (c350322c-bebd-11e7-b230-cf451ddd7335) after 60ms: <document type="freeswitch/xml"><section name="directory"><domain name="pbxdg.domain.net"><user id="user_f84u8dn62s"><variables><variable name="ecallmgr_Account-ID" value="75c5b9a0047e65399de45f41258e38e4"/><variable name="ecallmgr_Authorizing-Type" value="device"/><variable name="ecallmgr_Authorizing-ID" value="c04a2812eff90b41dd1282c4ffc03998"/><variable name="ecallmgr_Username" value="user_f84u8dn62s"/><variable name="ecallmgr_Realm" value="pbxdg.domain.net"/><variable name="ecallmgr_Account-Realm" value="pbxdg.domain.net"/><variable name="ecallmgr_Account-Name" value="Dove Gospel - Global"/><variable name="presence_id" value="888701@pbxdg.domain.net"/><variable name="ecallmgr_Owner-ID" value="9333eab27c60732f233e2b803e7c073b"/></variables><params><param name="password" value="ee61139cd193c08528c84683"/></params></user></domain></section></document> 2017-11-01 04:33:09.355383 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [received][100] 2017-11-01 04:33:09.355383 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=sems 838687344 1399990445 IN IP4 46.19.210.33 s=sems c=IN IP4 46.19.210.33 t=0 0 m=audio 21162 RTP/AVP 120 8 0 96 a=rtpmap:120 opus/48000/2 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=direction:both 2017-11-01 04:33:09.355383 [DEBUG] sofia.c:7486 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_NEW -> CS_INIT 2017-11-01 04:33:09.355383 [DEBUG] switch_core_state_machine.c:603 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State NEW 2017-11-01 04:33:09.355383 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_INIT (Cur 1 Tot 485) 2017-11-01 04:33:09.355383 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State INIT 2017-11-01 04:33:09.355383 [DEBUG] mod_sofia.c:90 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA INIT 2017-11-01 04:33:09.355383 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard INIT 2017-11-01 04:33:09.355383 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_INIT -> CS_ROUTING 2017-11-01 04:33:09.355383 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State INIT going to sleep 2017-11-01 04:33:09.355383 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_ROUTING (Cur 1 Tot 485) 2017-11-01 04:33:09.355383 [DEBUG] switch_channel.c:2249 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change DOWN -> RINGING 2017-11-01 04:33:09.355383 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State ROUTING 2017-11-01 04:33:09.355383 [DEBUG] mod_sofia.c:143 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA ROUTING 2017-11-01 04:33:09.355383 [DEBUG] switch_core_state_machine.c:236 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard ROUTING 2017-11-01 04:33:09.355383 [INFO] mod_dialplan_xml.c:637 Processing user_f84u8dn62s <user_f84u8dn62s>->888701 in context context_2 2017-11-01 04:33:09.355383 [DEBUG] kazoo_fetch_agent.c:216 Sending dialplan XML request (c359fd70-bebd-11e7-b232-cf451ddd7335) to ecallmgr@pbx01.exch1.net <1.1383.0> 2017-11-01 04:33:09.555173 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.1383.0> 2017-11-01 04:33:09.555173 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(371868A9-59F94E850003A182-C1C15700 ecallmgr_Call-Interaction-ID=63676729989-48a2eba5) 2017-11-01 04:33:09.575166 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24298.32> 2017-11-01 04:33:09.575166 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24299.32> 2017-11-01 04:33:09.575166 [DEBUG] kazoo_fetch_agent.c:277 Received dialplan XML (c359fd70-bebd-11e7-b232-cf451ddd7335) after 219ms: <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@pbx01.exch1.net won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=ecallmgr@pbx01.exch1.net"/><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=user_f84u8dn62s|ecallmgr_Realm=pbxdg.domain.net|presence_id=888701@pbxdg.domain.net|ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b|ecallmgr_Fetch-ID=c359fd70-bebd-11e7-b232-cf451ddd7335|ecallmgr_Caller-Screen-Bit=true|ecallmgr_Caller-Privacy-Hide-Number=false|ecallmgr_Caller-Privacy-Hide-Name=false|ecallmgr_Call-Interaction-ID=63676729989-48a2eba5|ecallmgr_Authorizing-Type=device|ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998|ecallmgr_Account-Realm=pbxdg.domain.net|ecallmgr_Account-Name=Dove Gospel - Global|ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4|ecallmgr_CallFlow-ID=3033db20be8da86ca844642e7578b780|ecallmgr_Channel-Authorized=true"/><action application="multiunset" data="^^;sip_h_X-AUTH-IP;sip_h_X-AUTH-PORT;sip_h_X-ecallmgr_Account-ID;sip_h_X-ecallmgr_Authorizing-Type;sip_h_X-ecallmgr_Authorizing-ID;sip_h_X-ecallmgr_Username;sip_h_X-ecallmgr_Realm;sip_h_X-ecallmgr_Account-Realm;sip_h_X-ecallmgr_Account-Name;sip_h_X-ecallmgr_Presence-ID;sip_h_X-ecallmgr_Owner-ID"/><action application="park"/></condition></extension></context></section></document> Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net parsing [context_2->park] continue=false Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Absolute Condition [park] Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action log(NOTICE log|${uuid}|ecallmgr@pbx01.exch1.net won call control) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action export(ecallmgr_Ecallmgr-Node=ecallmgr@pbx01.exch1.net) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action set(ringback=%(2000,4000,440,480)) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action set(transfer_ringback=%(2000,4000,440,480)) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action kz_multiset(^^|ecallmgr_Username=user_f84u8dn62s|ecallmgr_Realm=pbxdg.domain.net|presence_id=888701@pbxdg.domain.net|ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b|ecallmgr_Fetch-ID=c359fd70-bebd-11e7-b232-cf451ddd7335|ecallmgr_Caller-Screen-Bit=true|ecallmgr_Caller-Privacy-Hide-Number=false|ecallmgr_Caller-Privacy-Hide-Name=false|ecallmgr_Call-Interaction-ID=63676729989-48a2eba5|ecallmgr_Authorizing-Type=device|ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998|ecallmgr_Account-Realm=pbxdg.domain.net|ecallmgr_Account-Name=Dove Gospel - Global|ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4|ecallmgr_CallFlow-ID=3033db20be8da86ca844642e7578b780|ecallmgr_Channel-Authorized=true) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action multiunset(^^;sip_h_X-AUTH-IP;sip_h_X-AUTH-PORT;sip_h_X-ecallmgr_Account-ID;sip_h_X-ecallmgr_Authorizing-Type;sip_h_X-ecallmgr_Authorizing-ID;sip_h_X-ecallmgr_Username;sip_h_X-ecallmgr_Realm;sip_h_X-ecallmgr_Account-Realm;sip_h_X-ecallmgr_Account-Name;sip_h_X-ecallmgr_Presence-ID;sip_h_X-ecallmgr_Owner-ID) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action park() |--- Dialplan: Processing recursive conditions level:1 [park_recur_1] require-nested=TRUE |--- Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false |--- Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action export(ecallmgr_Bridge-ID=${UUID}) INLINE EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net export(ecallmgr_Bridge-ID=371868A9-59F94E850003A182-C1C15700) 2017-11-01 04:33:09.575166 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Bridge-ID]=[371868A9-59F94E850003A182-C1C15700] 2017-11-01 04:33:09.575166 [DEBUG] switch_core_state_machine.c:286 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_ROUTING -> CS_EXECUTE 2017-11-01 04:33:09.575166 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State ROUTING going to sleep 2017-11-01 04:33:09.575166 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_EXECUTE (Cur 1 Tot 485) 2017-11-01 04:33:09.575166 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State EXECUTE 2017-11-01 04:33:09.575166 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4249 2017-11-01 04:33:09.575166 [DEBUG] mod_sofia.c:198 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA EXECUTE 2017-11-01 04:33:09.575166 [DEBUG] switch_core_state_machine.c:328 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard EXECUTE EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net log(NOTICE log|371868A9-59F94E850003A182-C1C15700|ecallmgr@pbx01.exch1.net won call control) 2017-11-01 04:33:09.575166 [NOTICE] mod_dptools.c:1742 log|371868A9-59F94E850003A182-C1C15700|ecallmgr@pbx01.exch1.net won call control EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net export(ecallmgr_Ecallmgr-Node=ecallmgr@pbx01.exch1.net) 2017-11-01 04:33:09.575166 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallmgr@pbx01.exch1.net] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4311 EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net set(ringback=%(2000,4000,440,480)) 2017-11-01 04:33:09.575166 [DEBUG] mod_dptools.c:1548 SET sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net set(transfer_ringback=%(2000,4000,440,480)) 2017-11-01 04:33:09.575166 [DEBUG] mod_dptools.c:1548 SET sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [transfer_ringback]=[%(2000,4000,440,480)] EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net kz_multiset(^^|ecallmgr_Username=user_f84u8dn62s|ecallmgr_Realm=pbxdg.domain.net|presence_id=888701@pbxdg.domain.net|ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b|ecallmgr_Fetch-ID=c359fd70-bebd-11e7-b232-cf451ddd7335|ecallmgr_Caller-Screen-Bit=true|ecallmgr_Caller-Privacy-Hide-Number=false|ecallmgr_Caller-Privacy-Hide-Name=false|ecallmgr_Call-Interaction-ID=63676729989-48a2eba5|ecallmgr_Authorizing-Type=device|ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998|ecallmgr_Account-Realm=pbxdg.domain.net|ecallmgr_Account-Name=Dove Gospel - Global|ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4|ecallmgr_CallFlow-ID=3033db20be8da86ca844642e7578b780|ecallmgr_Channel-Authorized=true) 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Username]=[user_f84u8dn62s] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Realm]=[pbxdg.domain.net] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [presence_id]=[888701@pbxdg.domain.net] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Owner-ID]=[9333eab27c60732f233e2b803e7c073b] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Fetch-ID]=[c359fd70-bebd-11e7-b232-cf451ddd7335] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Screen-Bit]=[true] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Privacy-Hide-Number]=[false] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Privacy-Hide-Name]=[false] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Call-Interaction-ID]=[63676729989-48a2eba5] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Authorizing-Type]=[device] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Authorizing-ID]=[c04a2812eff90b41dd1282c4ffc03998] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-Realm]=[pbxdg.domain.net] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-Name]=[Dove Gospel - Global] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-ID]=[75c5b9a0047e65399de45f41258e38e4] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_CallFlow-ID]=[3033db20be8da86ca844642e7578b780] 2017-11-01 04:33:09.575166 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Channel-Authorized]=[true] 2017-11-01 04:33:09.585250 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4331 2017-11-01 04:33:09.585250 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4205 2017-11-01 04:33:09.585250 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4307 EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net multiunset(^^;sip_h_X-AUTH-IP;sip_h_X-AUTH-PORT;sip_h_X-ecallmgr_Account-ID;sip_h_X-ecallmgr_Authorizing-Type;sip_h_X-ecallmgr_Authorizing-ID;sip_h_X-ecallmgr_Username;sip_h_X-ecallmgr_Realm;sip_h_X-ecallmgr_Account-Realm;sip_h_X-ecallmgr_Account-Name;sip_h_X-ecallmgr_Presence-ID;sip_h_X-ecallmgr_Owner-ID) 2017-11-01 04:33:09.585250 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5111 EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net park() 2017-11-01 04:33:09.585250 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5958 2017-11-01 04:33:09.585250 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4460 2017-11-01 04:33:09.615364 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(371868A9-59F94E850003A182-C1C15700 ^^;ecallmgr_Username=user_f84u8dn62s;ecallmgr_Realm=pbxdg.domain.net;presence_id=888701@pbxdg.domain.net;ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b;ecallmgr_Fetch-ID=c359fd70-bebd-11e7-b232-cf451ddd7335;ecallmgr_Caller-Screen-Bit=true;ecallmgr_Caller-Privacy-Hide-Number=false;ecallmgr_Caller-Privacy-Hide-Name=false;ecallmgr_Call-Interaction-ID=63676729989-48a2eba5;ecallmgr_Authorizing-Type=device;ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998;ecallmgr_Account-Realm=pbxdg.domain.net;ecallmgr_Account-Name=Dove Gospel - Global;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;ecallmgr_CallFlow-ID=3033db20be8da86ca844642e7578b780;ecallmgr_Channel-Authorized=true;ecallmgr_Application-Node=kazoo_apps@pbx01.exch1.net;ecallmgr_Application-Name=callflow) 2017-11-01 04:33:09.645357 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24299.32> 2017-11-01 04:33:09.645357 [NOTICE] kazoo_node.c:430 log|371868A9-59F94E850003A182-C1C15700|executing kz_multiset ^^;ecallmgr_Username=user_f84u8dn62s;ecallmgr_Realm=pbxdg.domain.net;presence_id=888701@pbxdg.domain.net;ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b;ecallmgr_Fetch-ID=c359fd70-bebd-11e7-b232-cf451ddd7335;ecallmgr_Channel-Authorized=true;ecallmgr_Caller-Screen-Bit=true;ecallmgr_Caller-Privacy-Hide-Number=false;ecallmgr_Caller-Privacy-Hide-Name=false;ecallmgr_CallFlow-ID=3033db20be8da86ca844642e7578b780;ecallmgr_Call-Interaction-ID=63676729989-48a2eba5;ecallmgr_Authorizing-Type=device;ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998;ecallmgr_Application-Node=kazoo_apps@pbx01.exch1.net;ecallmgr_Application-Name=callflow;ecallmgr_Account-Realm=pbxdg.domain.net;ecallmgr_Account-Name=Dove Gospel - Global;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;effective_caller_id_number=888701;effective_caller_id_name=James Hughes 2017-11-01 04:33:09.665169 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute kz_multiset(^^;ecallmgr_Username=user_f84u8dn62s;ecallmgr_Realm=pbxdg.domain.net;presence_id=888701@pbxdg.domain.net;ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b;ecallmgr_Fetch-ID=c359fd70-bebd-11e7-b232-cf451ddd7335;ecallmgr_Channel-Authorized=true;ecallmgr_Caller-Screen-Bit=true;ecallmgr_Caller-Privacy-Hide-Number=false;ecallmgr_Caller-Privacy-Hide-Name=false;ecallmgr_CallFlow-ID=3033db20be8da86ca844642e7578b780;ecallmgr_Call-Interaction-ID=63676729989-48a2eba5;ecallmgr_Authorizing-Type=device;ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998;ecallmgr_Application-Node=kazoo_apps@pbx01.exch1.net;ecallmgr_Application-Name=callflow;ecallmgr_Account-Realm=pbxdg.domain.net;ecallmgr_Account-Name=Dove Gospel - Global;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;effective_caller_id_number=888701;effective_caller_id_name=James Hughes) EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net kz_multiset(^^;ecallmgr_Username=user_f84u8dn62s;ecallmgr_Realm=pbxdg.domain.net;presence_id=888701@pbxdg.domain.net;ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b;ecallmgr_Fetch-ID=c359fd70-bebd-11e7-b232-cf451ddd7335;ecallmgr_Channel-Authorized=true;ecallmgr_Caller-Screen-Bit=true;ecallmgr_Caller-Privacy-Hide-Number=false;ecallmgr_Caller-Privacy-Hide-Name=false;ecallmgr_CallFlow-ID=3033db20be8da86ca844642e7578b780;ecallmgr_Call-Interaction-ID=63676729989-48a2eba5;ecallmgr_Authorizing-Type=device;ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998;ecallmgr_Application-Node=kazoo_apps@pbx01.exch1.net;ecallmgr_Application-Name=callflow;ecallmgr_Account-Realm=pbxdg.domain.net;ecallmgr_Account-Name=Dove Gospel - Global;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;effective_caller_id_number=888701;effective_caller_id_name=James Hughes) 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Username]=[user_f84u8dn62s] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Realm]=[pbxdg.domain.net] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [presence_id]=[888701@pbxdg.domain.net] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Owner-ID]=[9333eab27c60732f233e2b803e7c073b] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Fetch-ID]=[c359fd70-bebd-11e7-b232-cf451ddd7335] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Channel-Authorized]=[true] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Screen-Bit]=[true] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Privacy-Hide-Number]=[false] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Privacy-Hide-Name]=[false] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_CallFlow-ID]=[3033db20be8da86ca844642e7578b780] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Call-Interaction-ID]=[63676729989-48a2eba5] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Authorizing-Type]=[device] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Authorizing-ID]=[c04a2812eff90b41dd1282c4ffc03998] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Application-Node]=[kazoo_apps@pbx01.exch1.net] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Application-Name]=[callflow] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-Realm]=[pbxdg.domain.net] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-Name]=[Dove Gospel - Global] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-ID]=[75c5b9a0047e65399de45f41258e38e4] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [effective_caller_id_number]=[888701] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [effective_caller_id_name]=[James Hughes] 2017-11-01 04:33:09.665169 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4849 2017-11-01 04:33:09.665169 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5784 2017-11-01 04:33:09.845329 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24319.32> 2017-11-01 04:33:09.845329 [NOTICE] kazoo_node.c:430 log|371868A9-59F94E850003A182-C1C15700|executing ring_ready 2017-11-01 04:33:09.865165 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute ring_ready() EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net ring_ready() 2017-11-01 04:33:09.865165 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net! send 998 bytes to udp/[KAZOOIP]:5060 at 04:33:09.870144: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bKfd1a.37859ae0b746929f182e0e4ec2f7fe79.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKpOioMaK2;rport=6050 Record-Route: <sip:KAZOOIP;lr=on;ftag=309022BA-59F94E850003A17D-C1C15700> From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=309022BA-59F94E850003A17D-C1C15700 To: <sip:888701@pbxdg.domain.net>;tag=49gcKgrc8ZB2S Call-ID: 371868A9-59F94E850003A182-C1C15700 CSeq: 10 INVITE Contact: <sip:888701@KAZOOIP: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-Length: 0 Remote-Party-ID: "888701" <sip:888701@pbxdg.domain.net>;party=calling;privacy=off;screen=no 2017-11-01 04:33:09.865165 [NOTICE] mod_dptools.c:1028 Ring Ready sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net! ------------------------------------------------------------------------ 2017-11-01 04:33:09.865165 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4103 2017-11-01 04:33:09.885472 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [early][180] 2017-11-01 04:33:10.045333 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24319.32> 2017-11-01 04:33:10.045333 [DEBUG] kazoo_node.c:1344 increased received message buffer size to 2275 2017-11-01 04:33:10.045333 [NOTICE] kazoo_node.c:447 log|371868A9-59F94E850003A182-C1C15700|building xferext extension: set continue_on_fail=true 2017-11-01 04:33:10.045333 [NOTICE] kazoo_node.c:447 log|371868A9-59F94E850003A182-C1C15700|building xferext extension: export sip_redirect_context=context_2 2017-11-01 04:33:10.045333 [NOTICE] kazoo_node.c:447 log|371868A9-59F94E850003A182-C1C15700|building xferext extension: set hangup_after_bridge=true 2017-11-01 04:33:10.045333 [NOTICE] kazoo_node.c:447 log|371868A9-59F94E850003A182-C1C15700|building xferext extension: export ecallmgr_Inception=${ecallmgr_Inception} 2017-11-01 04:33:10.045333 [NOTICE] kazoo_node.c:447 log|371868A9-59F94E850003A182-C1C15700|building xferext extension: export ecallmgr_Call-Interaction-ID=${ecallmgr_Call-Interaction-ID} 2017-11-01 04:33:10.045333 [NOTICE] kazoo_node.c:447 log|371868A9-59F94E850003A182-C1C15700|building xferext extension: bridge {call_timeout=30,originate_timeout=30,outbound_redirect_fatal='false',local_var_clobber='true'}[^^!ecallmgr_Username='user_vrf59sfv4q'!ecallmgr_Realm='pbxdg.domain.net'!presence_id='888701@pbxdg.domain.net'!origination_callee_id_number='888701'!origination_callee_id_name='James Hughes'!leg_timeout='30'!sip_h_X-KAZOO-AOR=sip:user_vrf59sfv4q@pbxdg.domain.net!sip_h_X-KAZOO-INVITE-FORMAT=contact!ecallmgr_Authorizing-ID='b2c525170e891ce12950790e47b5eb9f'!ecallmgr_Authorizing-Type='device'!ecallmgr_Owner-ID='9333eab27c60732f233e2b803e7c073b'!ecallmgr_Account-ID='75c5b9a0047e65399de45f41258e38e4'!sdp_secure_savp_only='true'!sip_invite_domain='pbxdg.domain.net'!absolute_codec_string='^^:PCMU:PCMA'!effective_callee_id_number='888701'!effective_callee_id_name='James Hughes']sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net;fs_path=sip:KAZOOIP,[^^!ecallmgr_Username='user_f84u8dn62s'!ecallmgr_Realm='pbxdg.domain.net'!presence_id='888701@pbxdg.domain.net'!origination_callee_id_number='888701'!origination_callee_id_name='James Hughes'!leg_timeout='30'!sip_h_X-KAZOO-AOR=sip:user_f84u8dn62s@pbxdg.domain.net!sip_h_X-KAZOO-INVITE-FORMAT=contact!ecallmgr_Authorizing-ID='c04a2812eff90b41dd1282c4ffc03998'!ecallmgr_Authorizing-Type='device'!ecallmgr_Owner-ID='9333eab27c60732f233e2b803e7c073b'!ecallmgr_Account-ID='75c5b9a0047e65399de45f41258e38e4'!sdp_secure_savp_only='true'!sip_invite_domain='pbxdg.domain.net'!absolute_codec_string='^^:PCMU:PCMA'!effective_callee_id_number='888701'!effective_callee_id_name='James Hughes']sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net;fs_path=sip:KAZOOIP 2017-11-01 04:33:10.045333 [NOTICE] kazoo_node.c:447 log|371868A9-59F94E850003A182-C1C15700|building xferext extension: event Event-Name=CUSTOM,Event-Subclass=kazoo::masquerade,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=bridge 2017-11-01 04:33:10.045333 [NOTICE] kazoo_node.c:447 log|371868A9-59F94E850003A182-C1C15700|building xferext extension: park 2017-11-01 04:33:10.045333 [NOTICE] kazoo_node.c:450 log|371868A9-59F94E850003A182-C1C15700|transfered call to xferext extension 2017-11-01 04:33:10.065175 [DEBUG] switch_channel.c:3170 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_EXECUTE -> CS_ROUTING 2017-11-01 04:33:10.065175 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State EXECUTE going to sleep 2017-11-01 04:33:10.065175 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_ROUTING (Cur 1 Tot 485) 2017-11-01 04:33:10.065175 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State ROUTING 2017-11-01 04:33:10.065175 [DEBUG] mod_sofia.c:143 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA ROUTING 2017-11-01 04:33:10.065175 [DEBUG] switch_core_state_machine.c:236 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard ROUTING 2017-11-01 04:33:10.065175 [DEBUG] switch_core_state_machine.c:256 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_ROUTING -> CS_EXECUTE 2017-11-01 04:33:10.065175 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State ROUTING going to sleep 2017-11-01 04:33:10.065175 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_EXECUTE (Cur 1 Tot 485) 2017-11-01 04:33:10.065175 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State EXECUTE 2017-11-01 04:33:10.065175 [DEBUG] mod_sofia.c:198 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA EXECUTE 2017-11-01 04:33:10.065175 [DEBUG] switch_core_state_machine.c:328 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard EXECUTE EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net set(continue_on_fail=true) 2017-11-01 04:33:10.065175 [DEBUG] mod_dptools.c:1548 SET sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [continue_on_fail]=[true] EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net export(sip_redirect_context=context_2) 2017-11-01 04:33:10.065175 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4109 2017-11-01 04:33:10.065175 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [sip_redirect_context]=[context_2] EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net set(hangup_after_bridge=true) 2017-11-01 04:33:10.065175 [DEBUG] mod_dptools.c:1548 SET sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [hangup_after_bridge]=[true] 2017-11-01 04:33:10.065175 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4217 EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net export(ecallmgr_Inception=) 2017-11-01 04:33:10.065175 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Inception]=[UNDEF] EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net export(ecallmgr_Call-Interaction-ID=63676729989-48a2eba5) 2017-11-01 04:33:10.065175 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4112 2017-11-01 04:33:10.075325 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Call-Interaction-ID]=[63676729989-48a2eba5] 2017-11-01 04:33:10.075325 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4110 EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net bridge({call_timeout=30,originate_timeout=30,outbound_redirect_fatal='false',local_var_clobber='true'}[^^!ecallmgr_Username='user_vrf59sfv4q'!ecallmgr_Realm='pbxdg.domain.net'!presence_id='888701@pbxdg.domain.net'!origination_callee_id_number='888701'!origination_callee_id_name='James Hughes'!leg_timeout='30'!sip_h_X-KAZOO-AOR=sip:user_vrf59sfv4q@pbxdg.domain.net!sip_h_X-KAZOO-INVITE-FORMAT=contact!ecallmgr_Authorizing-ID='b2c525170e891ce12950790e47b5eb9f'!ecallmgr_Authorizing-Type='device'!ecallmgr_Owner-ID='9333eab27c60732f233e2b803e7c073b'!ecallmgr_Account-ID='75c5b9a0047e65399de45f41258e38e4'!sdp_secure_savp_only='true'!sip_invite_domain='pbxdg.domain.net'!absolute_codec_string='^^:PCMU:PCMA'!effective_callee_id_number='888701'!effective_callee_id_name='James Hughes']sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net;fs_path=sip:KAZOOIP,[^^!ecallmgr_Username='user_f84u8dn62s'!ecallmgr_Realm='pbxdg.domain.net'!presence_id='888701@pbxdg.domain.net'!origination_callee_id_number='888701'!origination_callee_id_name='James Hughes'!leg_timeout='30'!sip_h_X-KAZOO-AOR=sip:user_f84u8dn62s@pbxdg.domain.net!sip_h_X-KAZOO-INVITE-FORMAT=contact!ecallmgr_Authorizing-ID='c04a2812eff90b41dd1282c4ffc03998'!ecallmgr_Authorizing-Type='device'!ecallmgr_Owner-ID='9333eab27c60732f233e2b803e7c073b'!ecallmgr_Account-ID='75c5b9a0047e65399de45f41258e38e4'!sdp_secure_savp_only='true'!sip_invite_domain='pbxdg.domain.net'!absolute_codec_string='^^:PCMU:PCMA'!effective_callee_id_number='888701'!effective_callee_id_name='James Hughes']sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net;fs_path=sip:KAZOOIP) 2017-11-01 04:33:10.075325 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4228 2017-11-01 04:33:10.075325 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[371868A9-59F94E850003A182-C1C15700] to event 2017-11-01 04:33:10.075325 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallmgr@pbx01.exch1.net] to event 2017-11-01 04:33:10.075325 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event 2017-11-01 04:33:10.075325 [DEBUG] switch_channel.c:1250 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net EXPORTING[export_vars] [ecallmgr_Call-Interaction-ID]=[63676729989-48a2eba5] to event 2017-11-01 04:33:10.075325 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2017-11-01 04:33:10.075325 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2017-11-01 04:33:10.075325 [NOTICE] switch_channel.c:1104 New Channel sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net [c3c6bfbe-bebd-11e7-b246-cf451ddd7335] 2017-11-01 04:33:10.075325 [DEBUG] mod_sofia.c:4819 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State Change CS_NEW -> CS_INIT 2017-11-01 04:33:10.075325 [DEBUG] switch_ivr_originate.c:2963 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Setting leg timeout to 30 2017-11-01 04:33:10.075325 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Running State Change CS_INIT (Cur 2 Tot 486) 2017-11-01 04:33:10.075325 [NOTICE] switch_channel.c:1104 New Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [c3c6dc38-bebd-11e7-b24c-cf451ddd7335] 2017-11-01 04:33:10.075325 [DEBUG] mod_sofia.c:4819 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_NEW -> CS_INIT 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State INIT 2017-11-01 04:33:10.075325 [DEBUG] mod_sofia.c:90 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net SOFIA INIT 2017-11-01 04:33:10.075325 [DEBUG] switch_ivr_originate.c:2963 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Setting leg timeout to 30 2017-11-01 04:33:10.075325 [DEBUG] sofia_glue.c:1264 sip:KAZOOIP Setting proxy route to sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net 2017-11-01 04:33:10.075325 [DEBUG] sofia_glue.c:1295 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net sending invite version: 1.6.19 64bit Local SDP: v=0 o=FreeSWITCH 1509489814 1509489815 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 20976 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 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_INIT (Cur 3 Tot 487) 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Standard INIT 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State Change CS_INIT -> CS_ROUTING 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State INIT going to sleep 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State INIT 2017-11-01 04:33:10.075325 [DEBUG] mod_sofia.c:90 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA INIT 2017-11-01 04:33:10.075325 [DEBUG] sofia_glue.c:1264 sip:KAZOOIP Setting proxy route to sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net 2017-11-01 04:33:10.075325 [DEBUG] sofia_glue.c:1295 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net sending invite version: 1.6.19 64bit Local SDP: v=0 o=FreeSWITCH 1509487154 1509487155 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 23636 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 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Running State Change CS_ROUTING (Cur 3 Tot 487) 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard INIT 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_INIT -> CS_ROUTING 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State INIT going to sleep send 1297 bytes to udp/[KAZOOIP]:5060 at 04:33:10.078991: ------------------------------------------------------------------------ INVITE sip:user_vrf59sfv4q@pbxdg.domain.net SIP/2.0 Via: SIP/2.0/UDP KAZOOIP:11000;rport;branch=z9hG4bKg6t1eXSN6556B Route: <sip:KAZOOIP> Max-Forwards: 49 From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=5ja5mB9F581mN To: <sip:user_vrf59sfv4q@pbxdg.domain.net> Call-ID: c3c6bfbe-bebd-11e7-b246-cf451ddd7335 CSeq: 114419331 INVITE Contact: <sip:mod_sofia@KAZOOIP: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: 268 X-KAZOO-AOR: sip:user_vrf59sfv4q@pbxdg.domain.net X-KAZOO-INVITE-FORMAT: contact X-FS-Support: update_display,send_info Remote-Party-ID: "James Hughes" <sip:888701@pbxdg.domain.net>;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1509489814 1509489815 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 20976 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 ------------------------------------------------------------------------ 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State ROUTING 2017-11-01 04:33:10.075325 [DEBUG] mod_sofia.c:143 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net SOFIA ROUTING 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_ROUTING (Cur 3 Tot 487) 2017-11-01 04:33:10.075325 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State ROUTING going to sleep 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State ROUTING 2017-11-01 04:33:10.075325 [DEBUG] mod_sofia.c:143 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA ROUTING 2017-11-01 04:33:10.075325 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State ROUTING going to sleep 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 487) 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State CONSUME_MEDIA 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State CONSUME_MEDIA going to sleep send 1297 bytes to udp/[KAZOOIP]:5060 at 04:33:10.079503: ------------------------------------------------------------------------ INVITE sip:user_f84u8dn62s@pbxdg.domain.net SIP/2.0 Via: SIP/2.0/UDP KAZOOIP:11000;rport;branch=z9hG4bKHFmtgraS3evSQ Route: <sip:KAZOOIP> Max-Forwards: 49 From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=6U3Xp6SK2Hr7g To: <sip:user_f84u8dn62s@pbxdg.domain.net> Call-ID: c3c6dc38-bebd-11e7-b24c-cf451ddd7335 CSeq: 114419331 INVITE Contact: <sip:mod_sofia@KAZOOIP:11000> User-Agent: 2600hz Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 487) 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: 268 X-KAZOO-AOR: sip:user_f84u8dn62s@pbxdg.domain.net X-KAZOO-INVITE-FORMAT: contact X-FS-Support: update_display,send_info Remote-Party-ID: "James Hughes" <sip:888701@pbxdg.domain.net>;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1509487154 1509487155 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 23636 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 ------------------------------------------------------------------------ 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State CONSUME_MEDIA 2017-11-01 04:33:10.075325 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State CONSUME_MEDIA going to sleep 2017-11-01 04:33:10.075325 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net entering state [calling][0] 2017-11-01 04:33:10.075325 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [calling][0] recv 348 bytes from udp/[KAZOOIP]:5060 at 04:33:10.080589: ------------------------------------------------------------------------ SIP/2.0 100 Attempting to connect your call Via: SIP/2.0/UDP KAZOOIP:11000;rport=11000;branch=z9hG4bKg6t1eXSN6556B;received=KAZOOIP From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=5ja5mB9F581mN To: <sip:user_vrf59sfv4q@pbxdg.domain.net> Call-ID: c3c6bfbe-bebd-11e7-b246-cf451ddd7335 CSeq: 114419331 INVITE Content-Length: 0 ------------------------------------------------------------------------ recv 348 bytes from udp/[KAZOOIP]:5060 at 04:33:10.080701: ------------------------------------------------------------------------ SIP/2.0 100 Attempting to connect your call Via: SIP/2.0/UDP KAZOOIP:11000;rport=11000;branch=z9hG4bKHFmtgraS3evSQ;received=KAZOOIP From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=6U3Xp6SK2Hr7g To: <sip:user_f84u8dn62s@pbxdg.domain.net> Call-ID: c3c6dc38-bebd-11e7-b24c-cf451ddd7335 CSeq: 114419331 INVITE Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:10.085174 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24319.32> 2017-11-01 04:33:10.085174 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(c3c6bfbe-bebd-11e7-b246-cf451ddd7335 ^^;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;ecallmgr_Global-Resource=false;ecallmgr_Channel-Authorized=true) 2017-11-01 04:33:10.085174 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24346.32> 2017-11-01 04:33:10.085174 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(c3c6dc38-bebd-11e7-b24c-cf451ddd7335 ^^;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;ecallmgr_Global-Resource=false;ecallmgr_Channel-Authorized=true) 2017-11-01 04:33:10.085174 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24350.32> 2017-11-01 04:33:10.085174 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(c3c6bfbe-bebd-11e7-b246-cf451ddd7335 ecallmgr_Call-Interaction-ID=63676729989-48a2eba5) 2017-11-01 04:33:10.285275 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24319.32> 2017-11-01 04:33:10.285275 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(c3c6dc38-bebd-11e7-b24c-cf451ddd7335 ecallmgr_Call-Interaction-ID=63676729989-48a2eba5) 2017-11-01 04:33:10.485439 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24319.32> recv 572 bytes from udp/[KAZOOIP]:5060 at 04:33:10.583382: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP KAZOOIP:11000;rport=11000;received=KAZOOIP;branch=z9hG4bKg6t1eXSN6556B Record-Route: <sip:KAZOOIP;lr;ftag=5ja5mB9F581mN> Call-ID: c3c6bfbe-bebd-11e7-b246-cf451ddd7335 From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=5ja5mB9F581mN To: <sip:user_vrf59sfv4q@pbxdg.domain.net>;tag=jy-cN.MOr8AHRLXRSpstujQwjZ2gLCvZ CSeq: 114419331 INVITE Contact: <sip:user_vrf59sfv4q@49.195.123.218:32106;ob> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:10.585175 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net entering state [proceeding][180] 2017-11-01 04:33:10.585175 [NOTICE] sofia.c:7192 Ring-Ready sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net! 2017-11-01 04:33:10.585175 [DEBUG] switch_channel.c:3346 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Callstate Change DOWN -> RINGING 2017-11-01 04:33:10.595315 [INFO] switch_ivr_originate.c:1215 Sending early media 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[opus:116:48000:20:0:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[G7221:115:32000:20:48000:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[G7221:107:16000:20:32000:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[G722:9:8000:20:64000:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[PCMU:0:8000:20:64000:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[PCMA:8:8000:20:64000:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[GSM:3:8000:20:13200:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[SPEEX:99:8000:20:24600:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:115:32000:20:48000:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:107:16000:20:32000:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-11-01 04:33:10.595315 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:115:32000:20:48000:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:107:16000:20:32000:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 96@8000 2017-11-01 04:33:10.605300 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [72000bps] 2017-11-01 04:33:10.605300 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [72000bps] 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:3061 Set Codec sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net opus/48000 20 ms 960 samples 0 bits 1 channels 2017-11-01 04:33:10.605300 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Original read codec set to opus:116 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:4767 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Set 2833 dtmf send payload to 96 recv payload to 96 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net] KAZOOIP port 26362 -> 46.19.210.33 port 21162 codec: 120 ms: 20 2017-11-01 04:33:10.605300 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 960 bytes per 20ms 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:7179 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Set 2833 dtmf send payload to 96 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:7186 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Set 2833 dtmf receive payload to 96 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:7209 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Set rtp dtmf delay to 40 2017-11-01 04:33:10.605300 [NOTICE] sofia_media.c:92 Pre-Answer sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net! 2017-11-01 04:33:10.605300 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5696 2017-11-01 04:33:10.605300 [DEBUG] switch_channel.c:3474 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change RINGING -> EARLY 2017-11-01 04:33:10.605300 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net. 2017-11-01 04:33:10.605300 [DEBUG] mod_sofia.c:2364 Ring SDP: v=0 o=FreeSWITCH 1509484428 1509484429 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 26362 RTP/AVP 120 96 a=rtpmap:120 opus/48000/2 a=fmtp:120 useinbandfec=1; minptime=10; maxptime=40 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 a=sendrecv 2017-11-01 04:33:10.605300 [DEBUG] switch_ivr_originate.c:1273 Raw Codec Activation Success L16@48000hz 1 channel 20ms 2017-11-01 04:33:10.605300 [DEBUG] switch_core_codec.c:223 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Push codec L16:100 2017-11-01 04:33:10.605300 [DEBUG] switch_ivr_originate.c:1342 Play Ringback Tone [%(2000,4000,440,480)] send 1322 bytes to udp/[KAZOOIP]:5060 at 04:33:10.609333: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bKfd1a.37859ae0b746929f182e0e4ec2f7fe79.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKpOioMaK2;rport=6050 Record-Route: <sip:KAZOOIP;lr=on;ftag=309022BA-59F94E850003A17D-C1C15700> From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=309022BA-59F94E850003A17D-C1C15700 To: <sip:888701@pbxdg.domain.net>;tag=49gcKgrc8ZB2S Call-ID: 371868A9-59F94E850003A182-C1C15700 CSeq: 10 INVITE Contact: <sip:888701@KAZOOIP: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: 277 Remote-Party-ID: "888701" <sip:888701@pbxdg.domain.net>;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1509484428 1509484429 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 26362 RTP/AVP 120 96 a=rtpmap:120 opus/48000/2 a=fmtp:120 useinbandfec=1; minptime=10; maxptime=40 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-11-01 04:33:10.625226 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [early][183] 2017-11-01 04:33:10.745250 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed. recv 497 bytes from udp/[KAZOOIP]:5060 at 04:33:11.236651: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Record-Route: <sip:KAZOOIP;lr=on;ftag=6U3Xp6SK2Hr7g> Via: SIP/2.0/UDP KAZOOIP:11000;received=KAZOOIP;rport=11000;branch=z9hG4bKHFmtgraS3evSQ From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=6U3Xp6SK2Hr7g To: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=51D5783F-59F94E8600021596-9719C700 Call-ID: c3c6dc38-bebd-11e7-b24c-cf451ddd7335 CSeq: 114419331 INVITE Server: call.center proxy Contact: <sip:46.19.210.33:6050;transport=udp> Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:11.235205 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [proceeding][180] 2017-11-01 04:33:11.235205 [NOTICE] sofia.c:7192 Ring-Ready sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net! 2017-11-01 04:33:11.235205 [DEBUG] switch_channel.c:3346 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change DOWN -> RINGING recv 337 bytes from udp/[KAZOOIP]:5060 at 04:33:13.805134: ------------------------------------------------------------------------ OPTIONS sip:KAZOOIP:11000 SIP/2.0 Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK75c2.28b2d0c2000000000000000000000000.0 To: <sip:KAZOOIP:11000> From: <sip:sipcheck@pbx01.exch1.net>;tag=21d4b410505c1ffc4306a41061c0d07d-9c88 CSeq: 10 OPTIONS Call-ID: 67f8977a2bce85b4-1807@KAZOOIP Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ send 701 bytes to udp/[KAZOOIP]:5060 at 04:33:13.805728: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK75c2.28b2d0c2000000000000000000000000.0 From: <sip:sipcheck@pbx01.exch1.net>;tag=21d4b410505c1ffc4306a41061c0d07d-9c88 To: <sip:KAZOOIP:11000>;tag=74vpr1aQZtetc Call-ID: 67f8977a2bce85b4-1807@KAZOOIP CSeq: 10 OPTIONS Contact: <sip:KAZOOIP: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 926 bytes from udp/[KAZOOIP]:5060 at 04:33:14.363691: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP KAZOOIP:11000;rport=11000;received=KAZOOIP;branch=z9hG4bKg6t1eXSN6556B Record-Route: <sip:KAZOOIP;lr;ftag=5ja5mB9F581mN> Call-ID: c3c6bfbe-bebd-11e7-b246-cf451ddd7335 From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=5ja5mB9F581mN To: <sip:user_vrf59sfv4q@pbxdg.domain.net>;tag=jy-cN.MOr8AHRLXRSpstujQwjZ2gLCvZ CSeq: 114419331 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Contact: <sip:user_vrf59sfv4q@49.195.123.218:32106;ob> Supported: replaces, 100rel, timer, norefersub Content-Type: application/sdp Content-Length: 277 v=0 o=- 3718499590 3718499591 IN IP4 49.195.123.218 s=pjmedia b=AS:117 t=0 0 a=X-nat:0 m=audio 32264 RTP/AVP 0 101 c=IN IP4 49.195.123.218 b=TIAS:96000 a=rtcp:4011 IN IP4 10.1.1.29 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 ------------------------------------------------------------------------ 2017-11-01 04:33:14.365175 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net entering state [completing][200] 2017-11-01 04:33:14.365175 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=- 3718499590 3718499591 IN IP4 49.195.123.218 s=pjmedia b=AS:117 t=0 0 a=X-nat:0 m=audio 32264 RTP/AVP 0 101 c=IN IP4 49.195.123.218 b=TIAS:96000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtcp:4011 IN IP4 10.1.1.29 send 478 bytes to udp/[KAZOOIP]:5060 at 04:33:14.365948: ------------------------------------------------------------------------ ACK sip:user_vrf59sfv4q@49.195.123.218:32106;ob SIP/2.0 Via: SIP/2.0/UDP KAZOOIP:11000;rport;branch=z9hG4bKjrDKjKUv0QjcK Route: <sip:KAZOOIP;lr;ftag=5ja5mB9F581mN> Max-Forwards: 70 From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=5ja5mB9F581mN To: <sip:user_vrf59sfv4q@pbxdg.domain.net>;tag=jy-cN.MOr8AHRLXRSpstujQwjZ2gLCvZ Call-ID: c3c6bfbe-bebd-11e7-b246-cf451ddd7335 CSeq: 114419331 ACK Contact: <sip:mod_sofia@KAZOOIP:11000> Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:14.365175 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net entering state [ready][200] 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:3061 Set Codec sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-11-01 04:33:14.365175 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Original read codec set to PCMU:0 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:4767 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Set 2833 dtmf send payload to 101 recv payload to 101 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net] KAZOOIP port 20976 -> 49.195.123.218 port 32264 codec: 0 ms: 20 2017-11-01 04:33:14.365175 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:7098 Activating RTCP PORT 4011 2017-11-01 04:33:14.365175 [DEBUG] switch_rtp.c:4507 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 4011 2017-11-01 04:33:14.365175 [DEBUG] switch_rtp.c:2567 Setting RTCP remote addr to 49.195.123.218:4011 2 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:7179 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Set 2833 dtmf send payload to 101 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:7186 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Set 2833 dtmf receive payload to 101 2017-11-01 04:33:14.365175 [DEBUG] switch_core_media.c:7209 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Set rtp dtmf delay to 40 2017-11-01 04:33:14.365175 [NOTICE] sofia.c:8218 Channel [sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net] has been answered 2017-11-01 04:33:14.365175 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4273 2017-11-01 04:33:14.365175 [DEBUG] switch_channel.c:3773 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Callstate Change RINGING -> ACTIVE 2017-11-01 04:33:14.385177 [DEBUG] switch_core_codec.c:248 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Restore previous codec opus:116. 2017-11-01 04:33:14.385177 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [CS_CONSUME_MEDIA] [LOSE_RACE] 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_HANGUP (Cur 3 Tot 487) 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:850 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change RINGING -> HANGUP 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State HANGUP 2017-11-01 04:33:14.385177 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net hanging up, cause: LOSE_RACE 2017-11-01 04:33:14.385177 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net. 2017-11-01 04:33:14.385177 [DEBUG] mod_sofia.c:850 Local SDP sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net: v=0 o=FreeSWITCH 1509484428 1509484430 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 26362 RTP/AVP 120 96 a=rtpmap:120 opus/48000/2 a=fmtp:120 useinbandfec=1; minptime=10; maxptime=40 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 a=sendrecv 2017-11-01 04:33:14.385177 [NOTICE] switch_ivr_originate.c:3647 Channel [sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net] has been answered send 1314 bytes to udp/[KAZOOIP]:5060 at 04:33:14.388964: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bKfd1a.37859ae0b746929f182e0e4ec2f7fe79.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKpOioMaK2;rport=6050 Record-Route: <sip:KAZOOIP;lr=on;ftag=309022BA-59F94E850003A17D-C1C15700> From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=309022BA-59F94E850003A17D-C1C15700 To: <sip:888701@pbxdg.domain.net>;tag=49gcKgrc8ZB2S Call-ID: 371868A9-59F94E850003A182-C1C15700 CSeq: 10 INVITE Contact: <sip:888701@KAZOOIP: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: 277 Remote-Party-ID: "James Hughes" <sip:888701@pbxdg.domain.net>;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1509484428 1509484429 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 26362 RTP/AVP 120 96 a=rtpmap:120 opus/48000/2 a=fmtp:120 useinbandfec=1; minptime=10; maxptime=40 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-11-01 04:33:14.385177 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 6172 2017-11-01 04:33:14.385177 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard HANGUP, cause: LOSE_RACE 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State HANGUP going to sleep 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:619 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_HANGUP -> CS_REPORTING 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_REPORTING (Cur 3 Tot 487) send 427 bytes to udp/[KAZOOIP]:5060 at 04:33:14.389328: ------------------------------------------------------------------------ CANCEL sip:user_f84u8dn62s@pbxdg.domain.net SIP/2.0 Via: SIP/2.0/UDP KAZOOIP:11000;rport;branch=z9hG4bKHFmtgraS3evSQ Route: <sip:KAZOOIP> Max-Forwards: 49 From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=6U3Xp6SK2Hr7g To: <sip:user_f84u8dn62s@pbxdg.domain.net> Call-ID: c3c6dc38-bebd-11e7-b24c-cf451ddd7335 CSeq: 114419331 CANCEL Reason: SIP;cause=200;text="Call completed elsewhere" Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State REPORTING 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:174 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard REPORTING, cause: LOSE_RACE 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State REPORTING going to sleep 2017-11-01 04:33:14.385177 [DEBUG] switch_channel.c:3773 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change EARLY -> ACTIVE 2017-11-01 04:33:14.385177 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [completed][200] 2017-11-01 04:33:14.385177 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net] recv 368 bytes from udp/[KAZOOIP]:5060 at 04:33:14.390080: ------------------------------------------------------------------------ SIP/2.0 200 canceling Via: SIP/2.0/UDP KAZOOIP:11000;rport=11000;branch=z9hG4bKHFmtgraS3evSQ;received=KAZOOIP From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=6U3Xp6SK2Hr7g To: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=ab22b7b63d1acec3822f69ec3f877ac8-9d6d Call-ID: c3c6dc38-bebd-11e7-b24c-cf451ddd7335 CSeq: 114419331 CANCEL Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:14.385177 [DEBUG] switch_ivr_bridge.c:1614 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:610 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_REPORTING -> CS_DESTROY 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Running State Change CS_EXCHANGE_MEDIA (Cur 3 Tot 487) 2017-11-01 04:33:14.385177 [DEBUG] switch_core_session.c:1665 Session 487 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Locked, Waiting on external entities 2017-11-01 04:33:14.385177 [NOTICE] switch_core_session.c:1683 Session 487 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Ended 2017-11-01 04:33:14.385177 [NOTICE] switch_core_session.c:1687 Close Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [CS_DESTROY] 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:653 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State EXCHANGE_MEDIA 2017-11-01 04:33:14.385177 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:741 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_DESTROY (Cur 2 Tot 487) 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State DESTROY 2017-11-01 04:33:14.385177 [DEBUG] mod_sofia.c:343 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA DESTROY 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:181 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard DESTROY 2017-11-01 04:33:14.385177 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State DESTROY going to sleep 2017-11-01 04:33:14.385177 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 6673 2017-11-01 04:33:14.385177 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4339 2017-11-01 04:33:14.445248 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed. 2017-11-01 04:33:14.445248 [NOTICE] switch_core_io.c:1202 Activating write resampler 2017-11-01 04:33:14.485174 [DEBUG] switch_rtp.c:1887 rtcp_stats_init: audio ssrc[148779877] base_seq[29029] recv 591 bytes from udp/[KAZOOIP]:5060 at 04:33:14.499001: ------------------------------------------------------------------------ ACK sip:888701@KAZOOIP:11000;transport=udp SIP/2.0 Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bKfd1a.ab6b44c8417cd4835d9bbbdae0d777f4.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bK~xuHba9B;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=309022BA-59F94E850003A17D-C1C15700 To: <sip:888701@pbxdg.domain.net>;tag=49gcKgrc8ZB2S CSeq: 10 ACK Call-ID: 371868A9-59F94E850003A182-C1C15700 Max-Forwards: 50 User-Agent: call.center proxy Contact: <sip:46.19.210.33:6050;transport=udp> Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 ------------------------------------------------------------------------ recv 460 bytes from udp/[KAZOOIP]:5060 at 04:33:14.499672: ------------------------------------------------------------------------ SIP/2.0 487 Request terminated Record-Route: <sip:KAZOOIP;lr=on;ftag=6U3Xp6SK2Hr7g> Via: SIP/2.0/UDP KAZOOIP:11000;received=KAZOOIP;rport=11000;branch=z9hG4bKHFmtgraS3evSQ From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=6U3Xp6SK2Hr7g To: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=51D5783F-59F94E8600021596-9719C700 Call-ID: c3c6dc38-bebd-11e7-b24c-cf451ddd7335 CSeq: 114419331 INVITE Server: call.center proxy Content-Length: 0 ------------------------------------------------------------------------ send 405 bytes to udp/[KAZOOIP]:5060 at 04:33:14.499857: ------------------------------------------------------------------------ ACK sip:user_f84u8dn62s@pbxdg.domain.net SIP/2.0 Via: SIP/2.0/UDP KAZOOIP:11000;rport;branch=z9hG4bKHFmtgraS3evSQ Route: <sip:KAZOOIP> Max-Forwards: 49 From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=6U3Xp6SK2Hr7g To: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=51D5783F-59F94E8600021596-9719C700 Call-ID: c3c6dc38-bebd-11e7-b24c-cf451ddd7335 CSeq: 114419331 ACK Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:14.505168 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [ready][200] 2017-11-01 04:33:14.505168 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed. 2017-11-01 04:33:14.505168 [NOTICE] switch_core_io.c:1202 Activating write resampler 2017-11-01 04:33:14.505168 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4383 2017-11-01 04:33:14.525162 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 6704 2017-11-01 04:33:15.645261 [INFO] switch_rtp.c:6700 Auto Changing audio RTCP port from 49.195.123.218:4011 to 49.195.123.218:32265 2017-11-01 04:33:15.645261 [DEBUG] switch_rtp.c:2567 Setting RTCP remote addr to 49.195.123.218:32265 2 recv 1376 bytes from udp/[KAZOOIP]:5060 at 04:33:20.452376: ------------------------------------------------------------------------ INVITE sip:888100@pbxdg.domain.net:5060;transport=udp SIP/2.0 Record-Route: <sip:KAZOOIP;lr=on;ftag=7BF47C90-59F94E9000060583-C1811700> Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK3b2e.81a7516715465afdd4fcc7bf384a3e5b.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKoAAQxaLu;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net> CSeq: 10 INVITE Call-ID: 08594CE6-59F94E9000060587-C1811700 Max-Forwards: 50 User-Agent: call.center proxy Content-Type: application/sdp Contact: <sip:46.19.210.33:6050;transport=udp> Content-Length: 261 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 X-ecallmgr_Account-ID: 75c5b9a0047e65399de45f41258e38e4 X-ecallmgr_Authorizing-Type: device X-ecallmgr_Authorizing-ID: c04a2812eff90b41dd1282c4ffc03998 X-ecallmgr_Username: user_f84u8dn62s X-ecallmgr_Realm: pbxdg.domain.net X-ecallmgr_Account-Realm: pbxdg.domain.net X-ecallmgr_Account-Name: Dove Gospel - Global X-ecallmgr_Presence-ID: 888701@pbxdg.domain.net X-ecallmgr_Owner-ID: 9333eab27c60732f233e2b803e7c073b v=0 o=sems 110182451 1227842507 IN IP4 46.19.210.33 s=sems c=IN IP4 46.19.210.33 t=0 0 m=audio 21168 RTP/AVP 120 8 0 96 a=rtpmap:120 opus/48000/2 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=sendrecv a=direction:both ------------------------------------------------------------------------ send 498 bytes to udp/[KAZOOIP]:5060 at 04:33:20.452839: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK3b2e.81a7516715465afdd4fcc7bf384a3e5b.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKoAAQxaLu;rport=6050 Record-Route: <sip:KAZOOIP;lr=on;ftag=7BF47C90-59F94E9000060583-C1811700> From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net> Call-ID: 08594CE6-59F94E9000060587-C1811700 CSeq: 10 INVITE User-Agent: 2600hz Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:20.445222 [NOTICE] switch_channel.c:1104 New Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [08594CE6-59F94E9000060587-C1811700] 2017-11-01 04:33:20.445222 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_NEW (Cur 3 Tot 488) 2017-11-01 04:33:20.445222 [DEBUG] sofia.c:9873 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net receiving invite from KAZOOIP:5060 version: 1.6.19 64bit 2017-11-01 04:33:20.445222 [DEBUG] sofia.c:9999 1 acls to check for proxy 2017-11-01 04:33:20.445222 [DEBUG] sofia.c:10004 checking KAZOOIP against acl authoritative 2017-11-01 04:33:20.445222 [INFO] sofia.c:10006 KAZOOIP is a proxy according to the authoritative acl 2017-11-01 04:33:20.445222 [DEBUG] sofia.c:10016 network ip is a proxy 2017-11-01 04:33:20.445222 [DEBUG] sofia.c:10020 found auth ip [X-AUTH-IP] header of [46.19.210.33] 2017-11-01 04:33:20.445222 [DEBUG] sofia.c:10044 IP KAZOOIP Rejected by acl "trusted". Falling back to Digest auth. 2017-11-01 04:33:20.445222 [DEBUG] kazoo_fetch_agent.c:216 Sending directory XML request (c9f61fc4-bebd-11e7-b251-cf451ddd7335) to ecallmgr@pbx01.exch1.net <1.1432.0> 2017-11-01 04:33:20.505244 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.1432.0> 2017-11-01 04:33:20.505244 [DEBUG] kazoo_fetch_agent.c:277 Received directory XML (c9f61fc4-bebd-11e7-b251-cf451ddd7335) after 60ms: <document type="freeswitch/xml"><section name="directory"><domain name="pbxdg.domain.net"><user id="user_f84u8dn62s"><variables><variable name="ecallmgr_Account-ID" value="75c5b9a0047e65399de45f41258e38e4"/><variable name="ecallmgr_Authorizing-Type" value="device"/><variable name="ecallmgr_Authorizing-ID" value="c04a2812eff90b41dd1282c4ffc03998"/><variable name="ecallmgr_Username" value="user_f84u8dn62s"/><variable name="ecallmgr_Realm" value="pbxdg.domain.net"/><variable name="ecallmgr_Account-Realm" value="pbxdg.domain.net"/><variable name="ecallmgr_Account-Name" value="Dove Gospel - Global"/><variable name="presence_id" value="888701@pbxdg.domain.net"/><variable name="ecallmgr_Owner-ID" value="9333eab27c60732f233e2b803e7c073b"/></variables><params><param name="password" value="fd52e9a77ee923563ef69629"/></params></user></domain></section></document> 2017-11-01 04:33:20.505244 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [received][100] 2017-11-01 04:33:20.505244 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=sems 110182451 1227842507 IN IP4 46.19.210.33 s=sems c=IN IP4 46.19.210.33 t=0 0 m=audio 21168 RTP/AVP 120 8 0 96 a=rtpmap:120 opus/48000/2 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=direction:both 2017-11-01 04:33:20.505244 [DEBUG] sofia.c:7486 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_NEW -> CS_INIT 2017-11-01 04:33:20.505244 [DEBUG] switch_core_state_machine.c:603 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State NEW 2017-11-01 04:33:20.505244 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_INIT (Cur 3 Tot 488) 2017-11-01 04:33:20.505244 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State INIT 2017-11-01 04:33:20.505244 [DEBUG] mod_sofia.c:90 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA INIT 2017-11-01 04:33:20.505244 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard INIT 2017-11-01 04:33:20.505244 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_INIT -> CS_ROUTING 2017-11-01 04:33:20.505244 [DEBUG] switch_core_state_machine.c:627 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State INIT going to sleep 2017-11-01 04:33:20.505244 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_ROUTING (Cur 3 Tot 488) 2017-11-01 04:33:20.505244 [DEBUG] switch_channel.c:2249 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change DOWN -> RINGING 2017-11-01 04:33:20.505244 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State ROUTING 2017-11-01 04:33:20.505244 [DEBUG] mod_sofia.c:143 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA ROUTING 2017-11-01 04:33:20.505244 [DEBUG] switch_core_state_machine.c:236 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard ROUTING 2017-11-01 04:33:20.505244 [INFO] mod_dialplan_xml.c:637 Processing user_f84u8dn62s <user_f84u8dn62s>->888100 in context context_2 2017-11-01 04:33:20.505244 [DEBUG] kazoo_fetch_agent.c:216 Sending dialplan XML request (c9feeaf0-bebd-11e7-b253-cf451ddd7335) to ecallmgr@pbx01.exch1.net <1.1383.0> 2017-11-01 04:33:20.705253 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.1383.0> 2017-11-01 04:33:20.705253 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(08594CE6-59F94E9000060587-C1811700 ecallmgr_Call-Interaction-ID=63676730000-a0d45d02) 2017-11-01 04:33:20.725174 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24406.32> 2017-11-01 04:33:20.725174 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24407.32> 2017-11-01 04:33:20.725174 [DEBUG] kazoo_fetch_agent.c:277 Received dialplan XML (c9feeaf0-bebd-11e7-b253-cf451ddd7335) after 219ms: <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@pbx01.exch1.net won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=ecallmgr@pbx01.exch1.net"/><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=user_f84u8dn62s|ecallmgr_Realm=pbxdg.domain.net|presence_id=888701@pbxdg.domain.net|ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b|ecallmgr_Fetch-ID=c9feeaf0-bebd-11e7-b253-cf451ddd7335|ecallmgr_Caller-Screen-Bit=true|ecallmgr_Caller-Privacy-Hide-Number=false|ecallmgr_Caller-Privacy-Hide-Name=false|ecallmgr_Call-Interaction-ID=63676730000-a0d45d02|ecallmgr_Authorizing-Type=device|ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998|ecallmgr_Account-Realm=pbxdg.domain.net|ecallmgr_Account-Name=Dove Gospel - Global|ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4|ecallmgr_CallFlow-ID=c6222420dbb9f58b6098337266eff6ec|ecallmgr_Channel-Authorized=true"/><action application="multiunset" data="^^;sip_h_X-AUTH-IP;sip_h_X-AUTH-PORT;sip_h_X-ecallmgr_Account-ID;sip_h_X-ecallmgr_Authorizing-Type;sip_h_X-ecallmgr_Authorizing-ID;sip_h_X-ecallmgr_Username;sip_h_X-ecallmgr_Realm;sip_h_X-ecallmgr_Account-Realm;sip_h_X-ecallmgr_Account-Name;sip_h_X-ecallmgr_Presence-ID;sip_h_X-ecallmgr_Owner-ID"/><action application="park"/></condition></extension></context></section></document> Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net parsing [context_2->park] continue=false Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Absolute Condition [park] Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action log(NOTICE log|${uuid}|ecallmgr@pbx01.exch1.net won call control) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action export(ecallmgr_Ecallmgr-Node=ecallmgr@pbx01.exch1.net) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action set(ringback=%(2000,4000,440,480)) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action set(transfer_ringback=%(2000,4000,440,480)) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action kz_multiset(^^|ecallmgr_Username=user_f84u8dn62s|ecallmgr_Realm=pbxdg.domain.net|presence_id=888701@pbxdg.domain.net|ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b|ecallmgr_Fetch-ID=c9feeaf0-bebd-11e7-b253-cf451ddd7335|ecallmgr_Caller-Screen-Bit=true|ecallmgr_Caller-Privacy-Hide-Number=false|ecallmgr_Caller-Privacy-Hide-Name=false|ecallmgr_Call-Interaction-ID=63676730000-a0d45d02|ecallmgr_Authorizing-Type=device|ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998|ecallmgr_Account-Realm=pbxdg.domain.net|ecallmgr_Account-Name=Dove Gospel - Global|ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4|ecallmgr_CallFlow-ID=c6222420dbb9f58b6098337266eff6ec|ecallmgr_Channel-Authorized=true) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action multiunset(^^;sip_h_X-AUTH-IP;sip_h_X-AUTH-PORT;sip_h_X-ecallmgr_Account-ID;sip_h_X-ecallmgr_Authorizing-Type;sip_h_X-ecallmgr_Authorizing-ID;sip_h_X-ecallmgr_Username;sip_h_X-ecallmgr_Realm;sip_h_X-ecallmgr_Account-Realm;sip_h_X-ecallmgr_Account-Name;sip_h_X-ecallmgr_Presence-ID;sip_h_X-ecallmgr_Owner-ID) Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action park() |--- Dialplan: Processing recursive conditions level:1 [park_recur_1] require-nested=TRUE |--- Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false |--- Dialplan: sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Action export(ecallmgr_Bridge-ID=${UUID}) INLINE EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net export(ecallmgr_Bridge-ID=08594CE6-59F94E9000060587-C1811700) 2017-11-01 04:33:20.725174 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Bridge-ID]=[08594CE6-59F94E9000060587-C1811700] 2017-11-01 04:33:20.725174 [DEBUG] switch_core_state_machine.c:286 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_ROUTING -> CS_EXECUTE 2017-11-01 04:33:20.725174 [DEBUG] switch_core_state_machine.c:643 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State ROUTING going to sleep 2017-11-01 04:33:20.725174 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_EXECUTE (Cur 3 Tot 488) 2017-11-01 04:33:20.725174 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State EXECUTE 2017-11-01 04:33:20.725174 [DEBUG] mod_sofia.c:198 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA EXECUTE 2017-11-01 04:33:20.725174 [DEBUG] switch_core_state_machine.c:328 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard EXECUTE EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net log(NOTICE log|08594CE6-59F94E9000060587-C1811700|ecallmgr@pbx01.exch1.net won call control) 2017-11-01 04:33:20.725174 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4249 2017-11-01 04:33:20.725174 [NOTICE] mod_dptools.c:1742 log|08594CE6-59F94E9000060587-C1811700|ecallmgr@pbx01.exch1.net won call control EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net export(ecallmgr_Ecallmgr-Node=ecallmgr@pbx01.exch1.net) 2017-11-01 04:33:20.725174 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallmgr@pbx01.exch1.net] EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net set(ringback=%(2000,4000,440,480)) 2017-11-01 04:33:20.725174 [DEBUG] mod_dptools.c:1548 SET sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net set(transfer_ringback=%(2000,4000,440,480)) 2017-11-01 04:33:20.725174 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4311 2017-11-01 04:33:20.725174 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4331 2017-11-01 04:33:20.725174 [DEBUG] mod_dptools.c:1548 SET sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [transfer_ringback]=[%(2000,4000,440,480)] EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net kz_multiset(^^|ecallmgr_Username=user_f84u8dn62s|ecallmgr_Realm=pbxdg.domain.net|presence_id=888701@pbxdg.domain.net|ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b|ecallmgr_Fetch-ID=c9feeaf0-bebd-11e7-b253-cf451ddd7335|ecallmgr_Caller-Screen-Bit=true|ecallmgr_Caller-Privacy-Hide-Number=false|ecallmgr_Caller-Privacy-Hide-Name=false|ecallmgr_Call-Interaction-ID=63676730000-a0d45d02|ecallmgr_Authorizing-Type=device|ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998|ecallmgr_Account-Realm=pbxdg.domain.net|ecallmgr_Account-Name=Dove Gospel - Global|ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4|ecallmgr_CallFlow-ID=c6222420dbb9f58b6098337266eff6ec|ecallmgr_Channel-Authorized=true) 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Username]=[user_f84u8dn62s] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Realm]=[pbxdg.domain.net] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [presence_id]=[888701@pbxdg.domain.net] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Owner-ID]=[9333eab27c60732f233e2b803e7c073b] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Fetch-ID]=[c9feeaf0-bebd-11e7-b253-cf451ddd7335] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Screen-Bit]=[true] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Privacy-Hide-Number]=[false] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Privacy-Hide-Name]=[false] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Call-Interaction-ID]=[63676730000-a0d45d02] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Authorizing-Type]=[device] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Authorizing-ID]=[c04a2812eff90b41dd1282c4ffc03998] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-Realm]=[pbxdg.domain.net] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-Name]=[Dove Gospel - Global] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-ID]=[75c5b9a0047e65399de45f41258e38e4] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_CallFlow-ID]=[c6222420dbb9f58b6098337266eff6ec] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Channel-Authorized]=[true] 2017-11-01 04:33:20.725174 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4205 EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net multiunset(^^;sip_h_X-AUTH-IP;sip_h_X-AUTH-PORT;sip_h_X-ecallmgr_Account-ID;sip_h_X-ecallmgr_Authorizing-Type;sip_h_X-ecallmgr_Authorizing-ID;sip_h_X-ecallmgr_Username;sip_h_X-ecallmgr_Realm;sip_h_X-ecallmgr_Account-Realm;sip_h_X-ecallmgr_Account-Name;sip_h_X-ecallmgr_Presence-ID;sip_h_X-ecallmgr_Owner-ID) 2017-11-01 04:33:20.725174 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4307 EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net park() 2017-11-01 04:33:20.725174 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5111 2017-11-01 04:33:20.725174 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5958 2017-11-01 04:33:20.725174 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4460 2017-11-01 04:33:20.765215 [INFO] kazoo_node.c:837 exec: kz_uuid_setvar_multi(08594CE6-59F94E9000060587-C1811700 ^^;ecallmgr_Username=user_f84u8dn62s;ecallmgr_Realm=pbxdg.domain.net;presence_id=888701@pbxdg.domain.net;ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b;ecallmgr_Fetch-ID=c9feeaf0-bebd-11e7-b253-cf451ddd7335;ecallmgr_Caller-Screen-Bit=true;ecallmgr_Caller-Privacy-Hide-Number=false;ecallmgr_Caller-Privacy-Hide-Name=false;ecallmgr_Call-Interaction-ID=63676730000-a0d45d02;ecallmgr_Authorizing-Type=device;ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998;ecallmgr_Account-Realm=pbxdg.domain.net;ecallmgr_Account-Name=Dove Gospel - Global;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;ecallmgr_CallFlow-ID=c6222420dbb9f58b6098337266eff6ec;ecallmgr_Channel-Authorized=true;ecallmgr_Application-Node=kazoo_apps@pbx01.exch1.net;ecallmgr_Application-Name=callflow) 2017-11-01 04:33:20.785222 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24407.32> 2017-11-01 04:33:20.785222 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing kz_multiset ^^;ecallmgr_Username=user_f84u8dn62s;ecallmgr_Realm=pbxdg.domain.net;presence_id=888701@pbxdg.domain.net;ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b;ecallmgr_Fetch-ID=c9feeaf0-bebd-11e7-b253-cf451ddd7335;ecallmgr_Channel-Authorized=true;ecallmgr_Caller-Screen-Bit=true;ecallmgr_Caller-Privacy-Hide-Number=false;ecallmgr_Caller-Privacy-Hide-Name=false;ecallmgr_CallFlow-ID=c6222420dbb9f58b6098337266eff6ec;ecallmgr_Call-Interaction-ID=63676730000-a0d45d02;ecallmgr_Authorizing-Type=device;ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998;ecallmgr_Application-Node=kazoo_apps@pbx01.exch1.net;ecallmgr_Application-Name=callflow;ecallmgr_Account-Realm=pbxdg.domain.net;ecallmgr_Account-Name=Dove Gospel - Global;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;effective_caller_id_number=888701;effective_caller_id_name=James Hughes 2017-11-01 04:33:20.785222 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute kz_multiset(^^;ecallmgr_Username=user_f84u8dn62s;ecallmgr_Realm=pbxdg.domain.net;presence_id=888701@pbxdg.domain.net;ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b;ecallmgr_Fetch-ID=c9feeaf0-bebd-11e7-b253-cf451ddd7335;ecallmgr_Channel-Authorized=true;ecallmgr_Caller-Screen-Bit=true;ecallmgr_Caller-Privacy-Hide-Number=false;ecallmgr_Caller-Privacy-Hide-Name=false;ecallmgr_CallFlow-ID=c6222420dbb9f58b6098337266eff6ec;ecallmgr_Call-Interaction-ID=63676730000-a0d45d02;ecallmgr_Authorizing-Type=device;ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998;ecallmgr_Application-Node=kazoo_apps@pbx01.exch1.net;ecallmgr_Application-Name=callflow;ecallmgr_Account-Realm=pbxdg.domain.net;ecallmgr_Account-Name=Dove Gospel - Global;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;effective_caller_id_number=888701;effective_caller_id_name=James Hughes) EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net kz_multiset(^^;ecallmgr_Username=user_f84u8dn62s;ecallmgr_Realm=pbxdg.domain.net;presence_id=888701@pbxdg.domain.net;ecallmgr_Owner-ID=9333eab27c60732f233e2b803e7c073b;ecallmgr_Fetch-ID=c9feeaf0-bebd-11e7-b253-cf451ddd7335;ecallmgr_Channel-Authorized=true;ecallmgr_Caller-Screen-Bit=true;ecallmgr_Caller-Privacy-Hide-Number=false;ecallmgr_Caller-Privacy-Hide-Name=false;ecallmgr_CallFlow-ID=c6222420dbb9f58b6098337266eff6ec;ecallmgr_Call-Interaction-ID=63676730000-a0d45d02;ecallmgr_Authorizing-Type=device;ecallmgr_Authorizing-ID=c04a2812eff90b41dd1282c4ffc03998;ecallmgr_Application-Node=kazoo_apps@pbx01.exch1.net;ecallmgr_Application-Name=callflow;ecallmgr_Account-Realm=pbxdg.domain.net;ecallmgr_Account-Name=Dove Gospel - Global;ecallmgr_Account-ID=75c5b9a0047e65399de45f41258e38e4;effective_caller_id_number=888701;effective_caller_id_name=James Hughes) 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Username]=[user_f84u8dn62s] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Realm]=[pbxdg.domain.net] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [presence_id]=[888701@pbxdg.domain.net] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Owner-ID]=[9333eab27c60732f233e2b803e7c073b] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Fetch-ID]=[c9feeaf0-bebd-11e7-b253-cf451ddd7335] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Channel-Authorized]=[true] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Screen-Bit]=[true] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Privacy-Hide-Number]=[false] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Caller-Privacy-Hide-Name]=[false] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_CallFlow-ID]=[c6222420dbb9f58b6098337266eff6ec] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Call-Interaction-ID]=[63676730000-a0d45d02] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Authorizing-Type]=[device] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Authorizing-ID]=[c04a2812eff90b41dd1282c4ffc03998] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Application-Node]=[kazoo_apps@pbx01.exch1.net] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Application-Name]=[callflow] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-Realm]=[pbxdg.domain.net] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-Name]=[Dove Gospel - Global] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [ecallmgr_Account-ID]=[75c5b9a0047e65399de45f41258e38e4] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [effective_caller_id_number]=[888701] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [effective_caller_id_name]=[James Hughes] 2017-11-01 04:33:20.785222 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4849 2017-11-01 04:33:20.785222 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5784 2017-11-01 04:33:20.985249 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> 2017-11-01 04:33:20.985249 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing answer 2017-11-01 04:33:20.985249 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute answer() EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net answer() 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[opus:116:48000:20:0:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[G7221:115:32000:20:48000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[G7221:107:16000:20:32000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[G722:9:8000:20:64000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[PCMU:0:8000:20:64000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[PCMA:8:8000:20:64000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[GSM:3:8000:20:13200:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:120:48000:20:0:2]/[SPEEX:99:8000:20:24600:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:115:32000:20:48000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:107:16000:20:32000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:115:32000:20:48000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:107:16000:20:32000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 96@8000 2017-11-01 04:33:20.995165 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [72000bps] 2017-11-01 04:33:20.995165 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [72000bps] 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:3061 Set Codec sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net opus/48000 20 ms 960 samples 0 bits 1 channels 2017-11-01 04:33:20.995165 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Original read codec set to opus:116 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:4767 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Set 2833 dtmf send payload to 96 recv payload to 96 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net] KAZOOIP port 27608 -> 46.19.210.33 port 21168 codec: 120 ms: 20 2017-11-01 04:33:20.995165 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 960 bytes per 20ms 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:7179 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Set 2833 dtmf send payload to 96 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:7186 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Set 2833 dtmf receive payload to 96 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:7209 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Set rtp dtmf delay to 40 2017-11-01 04:33:20.995165 [NOTICE] sofia_media.c:92 Pre-Answer sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net! 2017-11-01 04:33:20.995165 [DEBUG] switch_channel.c:3474 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change RINGING -> EARLY 2017-11-01 04:33:20.995165 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net. 2017-11-01 04:33:20.995165 [DEBUG] mod_sofia.c:850 Local SDP sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net: v=0 o=FreeSWITCH 1509483192 1509483193 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 27608 RTP/AVP 120 96 a=rtpmap:120 opus/48000/2 a=fmtp:120 useinbandfec=1; minptime=10; maxptime=40 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 a=sendrecv 2017-11-01 04:33:20.995165 [NOTICE] mod_dptools.c:1312 Channel [sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net] has been answered send 1333 bytes to udp/[KAZOOIP]:5060 at 04:33:20.998986: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK3b2e.81a7516715465afdd4fcc7bf384a3e5b.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKoAAQxaLu;rport=6050 2017-11-01 04:33:20.995165 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4292 Record-Route: <sip:KAZOOIP;lr=on;ftag=7BF47C90-59F94E9000060583-C1811700> From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net>;tag=8DpFtvUtv34cr Call-ID: 08594CE6-59F94E9000060587-C1811700 CSeq: 10 INVITE Contact: <sip:888100@KAZOOIP: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: 277 Remote-Party-ID: "888100" <sip:888100@pbxdg.domain.net>;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1509483192 1509483193 IN IP4 KAZOOIP s=FreeSWITCH c=IN IP4 KAZOOIP t=0 0 m=audio 27608 RTP/AVP 120 96 a=rtpmap:120 opus/48000/2 a=fmtp:120 useinbandfec=1; minptime=10; maxptime=40 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-11-01 04:33:20.995165 [DEBUG] switch_channel.c:3773 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change EARLY -> ACTIVE 2017-11-01 04:33:20.995165 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [completed][200] 2017-11-01 04:33:20.995165 [DEBUG] switch_ivr.c:980 Codec Activated L16@48000hz 1 channels 20ms 2017-11-01 04:33:20.995165 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4354 recv 591 bytes from udp/[KAZOOIP]:5060 at 04:33:21.109686: ------------------------------------------------------------------------ ACK sip:888100@KAZOOIP:11000;transport=udp SIP/2.0 Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK3b2e.a5aa2236aaf932d11d449b468d06bf55.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKxJuAKapu;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net>;tag=8DpFtvUtv34cr CSeq: 10 ACK Call-ID: 08594CE6-59F94E9000060587-C1811700 Max-Forwards: 50 User-Agent: call.center proxy Contact: <sip:46.19.210.33:6050;transport=udp> Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 ------------------------------------------------------------------------ 2017-11-01 04:33:21.115176 [DEBUG] sofia.c:7084 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net entering state [ready][200] 2017-11-01 04:33:21.135209 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed. 2017-11-01 04:33:21.185193 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> 2017-11-01 04:33:21.185193 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing kz_multiset playback_terminators=#*0123456789 2017-11-01 04:33:21.195243 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute kz_multiset(playback_terminators=#*0123456789) EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net kz_multiset(playback_terminators=#*0123456789) 2017-11-01 04:33:21.195243 [DEBUG] kazoo_dptools.c:81 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SET [playback_terminators]=[#*0123456789] 2017-11-01 04:33:21.195243 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4324 2017-11-01 04:33:21.195243 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4547 2017-11-01 04:33:21.385285 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> 2017-11-01 04:33:21.385285 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing playback ${http_get http://127.0.0.1:15984/account%2F75%2Fc5%2Fb9a0047e65399de45f41258e38e4/ef89902e88c1ae916b0839a0779854df/uploaded_file_63676119931.mp3?rev=2-b9a54446bf51f47f1ee80b327ed1f2f0} 2017-11-01 04:33:21.395211 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute playback(${http_get http://127.0.0.1:15984/account%2F75%2Fc5%2Fb9a0047e65399de45f41258e38e4/ef89902e88c1ae916b0839a0779854df/uploaded_file_63676119931.mp3?rev=2-b9a54446bf51f47f1ee80b327ed1f2f0}) 2017-11-01 04:33:21.395211 [DEBUG] mod_http_cache.c:659 Locked cache 2017-11-01 04:33:21.395211 [DEBUG] mod_http_cache.c:796 Cache HIT: size = 90 (34 MB), hit ratio = 553/643 2017-11-01 04:33:21.395211 [DEBUG] mod_http_cache.c:670 Unlocked cache EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net playback(/usr/share/kazoo-freeswitch/sounds/http_cache/6c/fa4584-bebd-11e7-b22a-cf451ddd7335.mp3) 2017-11-01 04:33:21.395211 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@48000hz 1 channels 20ms 2017-11-01 04:33:21.585172 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> 2017-11-01 04:33:23.595173 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/kazoo-freeswitch/sounds/http_cache/6c/fa4584-bebd-11e7-b22a-cf451ddd7335.mp3 2017-11-01 04:33:23.595173 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4622 2017-11-01 04:33:23.595173 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing event Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=6526d6f4bafb796cca90ba812c157873 2017-11-01 04:33:23.615220 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute event(Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=6526d6f4bafb796cca90ba812c157873) EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net event(Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=6526d6f4bafb796cca90ba812c157873) 2017-11-01 04:33:23.615220 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4694 2017-11-01 04:33:23.615220 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4790 2017-11-01 04:33:23.795170 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> recv 337 bytes from udp/[KAZOOIP]:5060 at 04:33:23.805025: ------------------------------------------------------------------------ OPTIONS sip:KAZOOIP:11000 SIP/2.0 Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK85c2.284f2bb7000000000000000000000000.0 To: <sip:KAZOOIP:11000> From: <sip:sipcheck@pbx01.exch1.net>;tag=21d4b410505c1ffc4306a41061c0d07d-08b1 CSeq: 10 OPTIONS Call-ID: 67f8977a2bce85b5-1807@KAZOOIP Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ send 701 bytes to udp/[KAZOOIP]:5060 at 04:33:23.805495: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK85c2.284f2bb7000000000000000000000000.0 From: <sip:sipcheck@pbx01.exch1.net>;tag=21d4b410505c1ffc4306a41061c0d07d-08b1 To: <sip:KAZOOIP:11000>;tag=9pF8UQcyScUZK Call-ID: 67f8977a2bce85b5-1807@KAZOOIP CSeq: 10 OPTIONS Contact: <sip:KAZOOIP: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 ------------------------------------------------------------------------ 2017-11-01 04:33:24.625185 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing playback silence_stream://50 2017-11-01 04:33:24.635171 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute playback(silence_stream://50) EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net playback(silence_stream://50) 2017-11-01 04:33:24.635171 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@48000hz 1 channels 20ms 2017-11-01 04:33:24.695164 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://50 2017-11-01 04:33:24.695164 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4439 2017-11-01 04:33:24.825167 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> 2017-11-01 04:33:24.825167 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing event Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=1c5547a5825c7cab7ca2fc6a96ffee01 2017-11-01 04:33:24.835165 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute event(Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=1c5547a5825c7cab7ca2fc6a96ffee01) EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net event(Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=1c5547a5825c7cab7ca2fc6a96ffee01) 2017-11-01 04:33:24.835165 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4694 2017-11-01 04:33:24.835165 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4790 2017-11-01 04:33:25.025172 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> 2017-11-01 04:33:25.025172 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing answer 2017-11-01 04:33:25.035172 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute answer() EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net answer() 2017-11-01 04:33:25.035172 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4331 2017-11-01 04:33:25.225171 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> 2017-11-01 04:33:25.225171 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing playback ${http_get http://127.0.0.1:15984/account%2F75%2Fc5%2Fb9a0047e65399de45f41258e38e4/8dcb826a9d2465a0842b13c6bb2c30a2/uploaded_file_63676719064.mp3?rev=20-48b8bbc7cc2ea2c52ed06b7de54aef3c} 2017-11-01 04:33:25.235220 [DEBUG] switch_ivr.c:623 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Command Execute playback(${http_get http://127.0.0.1:15984/account%2F75%2Fc5%2Fb9a0047e65399de45f41258e38e4/8dcb826a9d2465a0842b13c6bb2c30a2/uploaded_file_63676719064.mp3?rev=20-48b8bbc7cc2ea2c52ed06b7de54aef3c}) 2017-11-01 04:33:25.235220 [DEBUG] mod_http_cache.c:659 Locked cache 2017-11-01 04:33:25.235220 [DEBUG] mod_http_cache.c:796 Cache HIT: size = 90 (34 MB), hit ratio = 554/644 2017-11-01 04:33:25.235220 [DEBUG] mod_http_cache.c:670 Unlocked cache EXECUTE sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net playback(/usr/share/kazoo-freeswitch/sounds/http_cache/88/5b2e10-bea4-11e7-b037-cf451ddd7335.mp3) 2017-11-01 04:33:25.235220 [WARNING] switch_core_file.c:360 File has 2 channels, muxing to 1 channel will occur. 2017-11-01 04:33:25.235220 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@48000hz 1 channels 20ms 2017-11-01 04:33:25.425177 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> recv 543 bytes from udp/[KAZOOIP]:5060 at 04:33:25.679179: ------------------------------------------------------------------------ BYE sip:888100@KAZOOIP:11000;transport=udp SIP/2.0 Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK1b2e.ce585754859e443b4764743c20a7b39d.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bK6lM6Datc;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net>;tag=8DpFtvUtv34cr CSeq: 12 BYE Call-ID: 08594CE6-59F94E9000060587-C1811700 Max-Forwards: 50 User-Agent: call.center proxy Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 ------------------------------------------------------------------------ recv 1287 bytes from udp/[KAZOOIP]:5060 at 04:33:25.682876: ------------------------------------------------------------------------ REFER sip:888100@KAZOOIP:11000;transport=udp SIP/2.0 Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK4b2e.70b16b32b7c17b8954d52f73378b9395.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKSfzxBaEw;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net>;tag=8DpFtvUtv34cr CSeq: 11 REFER Call-ID: 08594CE6-59F94E9000060587-C1811700 Max-Forwards: 50 Refer-To: <sip:888701@pbxdg.domain.net;transport=tcp?Replaces=from-tag%3D2MmjJy6lx0AU9GCxUleos5IZYh1wnS1b%3Bh8f945jJkMIAobkKwGnAEa0QFY.J6bTm%3Bto-tag%3D594447DA-59F94E8500039E2C-9709B700&Require=replaces> Referred-By: <sip:user_f84u8dn62s@pbxdg.domain.net>;transport=tcp User-Agent: call.center proxy Contact: <sip:46.19.210.33:6050;transport=udp> Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 X-ecallmgr_Account-ID: 75c5b9a0047e65399de45f41258e38e4 X-ecallmgr_Authorizing-Type: device X-ecallmgr_Authorizing-ID: c04a2812eff90b41dd1282c4ffc03998 X-ecallmgr_Username: user_f84u8dn62s X-ecallmgr_Realm: pbxdg.domain.net X-ecallmgr_Account-Realm: pbxdg.domain.net X-ecallmgr_Account-Name: Dove Gospel - Global X-ecallmgr_Presence-ID: 888701@pbxdg.domain.net X-ecallmgr_Owner-ID: 9333eab27c60732f233e2b803e7c073b ------------------------------------------------------------------------ send 430 bytes to udp/[KAZOOIP]:5060 at 04:33:25.683064: ------------------------------------------------------------------------ SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK4b2e.70b16b32b7c17b8954d52f73378b9395.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKSfzxBaEw;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net>;tag=8DpFtvUtv34cr Call-ID: 08594CE6-59F94E9000060587-C1811700 CSeq: 11 REFER Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:25.695176 [NOTICE] sofia.c:1012 Hangup sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [CS_EXECUTE] [NORMAL_CLEARING] 2017-11-01 04:33:25.695176 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/kazoo-freeswitch/sounds/http_cache/88/5b2e10-bea4-11e7-b037-cf451ddd7335.mp3 send 566 bytes to udp/[KAZOOIP]:5060 at 04:33:25.697396: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK1b2e.ce585754859e443b4764743c20a7b39d.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bK6lM6Datc;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net>;tag=8DpFtvUtv34cr Call-ID: 08594CE6-59F94E9000060587-C1811700 CSeq: 12 BYE User-Agent: 2600hz Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:25.695176 [DEBUG] switch_core_session.c:2815 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-11-01 04:33:25.695176 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4714 2017-11-01 04:33:25.695176 [DEBUG] switch_core_session.c:2815 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State EXECUTE going to sleep 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_HANGUP (Cur 3 Tot 488) 2017-11-01 04:33:25.695176 [DEBUG] switch_ivr.c:666 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net skip receive message [AUDIO_SYNC] (channel is hungup already) 2017-11-01 04:33:25.695176 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4568 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:850 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change ACTIVE -> HANGUP 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State HANGUP 2017-11-01 04:33:25.695176 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net hanging up, cause: NORMAL_CLEARING 2017-11-01 04:33:25.695176 [NOTICE] kazoo_node.c:430 log|08594CE6-59F94E9000060587-C1811700|executing event Event-Subclass=kazoo::noop,Event-Name=CUSTOM,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=noop,kazoo_application_response=c57918ba818a6982a08370893db4c5c3 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard HANGUP, cause: NORMAL_CLEARING 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State HANGUP going to sleep 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:619 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_HANGUP -> CS_REPORTING 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_REPORTING (Cur 3 Tot 488) 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State REPORTING 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:174 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard REPORTING, cause: NORMAL_CLEARING 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State REPORTING going to sleep 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:610 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_REPORTING -> CS_DESTROY 2017-11-01 04:33:25.695176 [DEBUG] switch_core_session.c:1665 Session 488 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Locked, Waiting on external entities 2017-11-01 04:33:25.695176 [NOTICE] switch_core_session.c:1683 Session 488 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Ended 2017-11-01 04:33:25.695176 [NOTICE] switch_core_session.c:1687 Close Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [CS_DESTROY] 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:741 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_DESTROY (Cur 2 Tot 488) 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State DESTROY 2017-11-01 04:33:25.695176 [DEBUG] mod_sofia.c:343 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA DESTROY 2017-11-01 04:33:25.695176 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2017-11-01 04:33:25.695176 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2017-11-01 04:33:25.695176 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2017-11-01 04:33:25.695176 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[234] Bytes encoded[21498] Encoded length ms[4680] Average encoded bitrate bps[42996] 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:181 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard DESTROY 2017-11-01 04:33:25.695176 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State DESTROY going to sleep 2017-11-01 04:33:25.695176 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4844 2017-11-01 04:33:25.895169 [DEBUG] kazoo_node.c:1319 Sent erlang message to ecallmgr@pbx01.exch1.net <1.24424.32> recv 543 bytes from udp/[KAZOOIP]:5060 at 04:33:26.595347: ------------------------------------------------------------------------ BYE sip:888701@KAZOOIP:11000;transport=udp SIP/2.0 Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK0e1a.dac0aaebe694d5c3f2667ffa2ee6d9e4.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bK2~gpKaIk;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=309022BA-59F94E850003A17D-C1C15700 To: <sip:888701@pbxdg.domain.net>;tag=49gcKgrc8ZB2S CSeq: 11 BYE Call-ID: 371868A9-59F94E850003A182-C1C15700 Max-Forwards: 50 User-Agent: call.center proxy Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 ------------------------------------------------------------------------ 2017-11-01 04:33:26.605213 [NOTICE] sofia.c:1012 Hangup sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [CS_EXECUTE] [NORMAL_CLEARING] send 566 bytes to udp/[KAZOOIP]:5060 at 04:33:26.607594: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK0e1a.dac0aaebe694d5c3f2667ffa2ee6d9e4.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bK2~gpKaIk;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=309022BA-59F94E850003A17D-C1C15700 To: <sip:888701@pbxdg.domain.net>;tag=49gcKgrc8ZB2S Call-ID: 371868A9-59F94E850003A182-C1C15700 CSeq: 11 BYE User-Agent: 2600hz Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2017-11-01 04:33:26.605213 [DEBUG] switch_ivr_bridge.c:706 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net ending bridge by request from write function 2017-11-01 04:33:26.605213 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net] 2017-11-01 04:33:26.605213 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net] 2017-11-01 04:33:26.605213 [NOTICE] switch_ivr_bridge.c:904 Hangup sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:653 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State EXCHANGE_MEDIA going to sleep 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Running State Change CS_HANGUP (Cur 2 Tot 488) 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:850 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Callstate Change ACTIVE -> HANGUP 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State HANGUP 2017-11-01 04:33:26.605213 [DEBUG] mod_sofia.c:432 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Overriding SIP cause 480 with 200 from the other leg 2017-11-01 04:33:26.605213 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net hanging up, cause: NORMAL_CLEARING 2017-11-01 04:33:26.605213 [DEBUG] switch_ivr_bridge.c:1712 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net skip receive message [UNBRIDGE] (channel is hungup already) 2017-11-01 04:33:26.605213 [DEBUG] switch_ivr_bridge.c:1715 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net skip receive message [UNBRIDGE] (channel is hungup already) 2017-11-01 04:33:26.605213 [DEBUG] switch_core_session.c:2815 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:650 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State EXECUTE going to sleep 2017-11-01 04:33:26.605213 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_HANGUP (Cur 2 Tot 488) 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Standard HANGUP, cause: NORMAL_CLEARING 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State HANGUP going to sleep 2017-11-01 04:33:26.605213 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 6931 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:619 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State Change CS_HANGUP -> CS_REPORTING 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:850 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Callstate Change ACTIVE -> HANGUP 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Running State Change CS_REPORTING (Cur 2 Tot 488) 2017-11-01 04:33:26.605213 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 8523 send 681 bytes to udp/[KAZOOIP]:5060 at 04:33:26.610424: ------------------------------------------------------------------------ BYE sip:user_vrf59sfv4q@49.195.123.218:32106;ob SIP/2.0 Via: SIP/2.0/UDP KAZOOIP:11000;rport;branch=z9hG4bKK16Bmec0X08ye Route: <sip:KAZOOIP;lr;ftag=5ja5mB9F581mN> Max-Forwards: 70 From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=5ja5mB9F581mN To: <sip:user_vrf59sfv4q@pbxdg.domain.net>;tag=jy-cN.MOr8AHRLXRSpstujQwjZ2gLCvZ Call-ID: c3c6bfbe-bebd-11e7-b246-cf451ddd7335 CSeq: 114419332 BYE User-Agent: 2600hz Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State HANGUP Reason: Q.850;cause=16;text="NORMAL_CLEARING" 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State REPORTING Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:174 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Standard REPORTING, cause: NORMAL_CLEARING 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State REPORTING going to sleep ------------------------------------------------------------------------ 2017-11-01 04:33:26.605213 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net hanging up, cause: NORMAL_CLEARING 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:610 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State Change CS_REPORTING -> CS_DESTROY 2017-11-01 04:33:26.605213 [DEBUG] switch_core_session.c:1665 Session 486 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Locked, Waiting on external entities 2017-11-01 04:33:26.605213 [NOTICE] switch_core_session.c:1683 Session 486 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Ended 2017-11-01 04:33:26.605213 [NOTICE] switch_core_session.c:1687 Close Channel sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net [CS_DESTROY] 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard HANGUP, cause: NORMAL_CLEARING 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:852 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State HANGUP going to sleep 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:619 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_HANGUP -> CS_REPORTING 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:741 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) Running State Change CS_DESTROY (Cur 1 Tot 488) 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:584 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_REPORTING (Cur 1 Tot 488) 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State DESTROY 2017-11-01 04:33:26.605213 [DEBUG] mod_sofia.c:343 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net SOFIA DESTROY 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State REPORTING 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:174 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard REPORTING, cause: NORMAL_CLEARING 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:938 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State REPORTING going to sleep 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:181 sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net Standard DESTROY 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_vrf59sfv4q@pbxdg.domain.net) State DESTROY going to sleep 2017-11-01 04:33:26.605213 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4874 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:610 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State Change CS_REPORTING -> CS_DESTROY 2017-11-01 04:33:26.605213 [DEBUG] switch_core_session.c:1665 Session 485 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Locked, Waiting on external entities 2017-11-01 04:33:26.605213 [NOTICE] switch_core_session.c:1683 Session 485 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Ended 2017-11-01 04:33:26.605213 [NOTICE] switch_core_session.c:1687 Close Channel sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net [CS_DESTROY] 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:741 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) Running State Change CS_DESTROY (Cur 0 Tot 488) 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State DESTROY 2017-11-01 04:33:26.605213 [DEBUG] mod_sofia.c:343 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net SOFIA DESTROY 2017-11-01 04:33:26.605213 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[306] PLC[0] FEC[0] 2017-11-01 04:33:26.605213 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2017-11-01 04:33:26.605213 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2017-11-01 04:33:26.605213 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[795] Bytes encoded[72304] Encoded length ms[15900] Average encoded bitrate bps[38562] 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:181 sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net Standard DESTROY 2017-11-01 04:33:26.605213 [DEBUG] switch_core_state_machine.c:751 (sofia/sipinterface_1/user_f84u8dn62s@pbxdg.domain.net) State DESTROY going to sleep 2017-11-01 04:33:26.605213 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 7230 recv 354 bytes from udp/[KAZOOIP]:5060 at 04:33:26.863223: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP KAZOOIP:11000;rport=11000;received=KAZOOIP;branch=z9hG4bKK16Bmec0X08ye Call-ID: c3c6bfbe-bebd-11e7-b246-cf451ddd7335 From: "James Hughes" <sip:888701@pbxdg.domain.net>;tag=5ja5mB9F581mN To: <sip:user_vrf59sfv4q@pbxdg.domain.net>;tag=jy-cN.MOr8AHRLXRSpstujQwjZ2gLCvZ CSeq: 114419332 BYE Content-Length: 0 ------------------------------------------------------------------------ Here is the full log as requested, I hope it helps shed some light on what may be happening. Please let me know If I can provide anything further. Quote
Administrators Darren Schreiber Posted November 1, 2017 Administrators Report Posted November 1, 2017 FreeSWITCH is correctly producing an error because the packets are arriving out-of-order and contradictory. In SIP (this has nothing to do with Kazoo or FreeSWITCH btw) each packet has a CSeq number which is a sequencing number. It's expected to show up in order: recv 543 bytes from udp/[KAZOOIP]:5060 at 04:33:25.679179: ------------------------------------------------------------------------ BYE sip:888100@KAZOOIP:11000;transport=udp SIP/2.0 Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK1b2e.ce585754859e443b4764743c20a7b39d.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bK6lM6Datc;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net>;tag=8DpFtvUtv34cr CSeq: 12 BYE Call-ID: 08594CE6-59F94E9000060587-C1811700 Max-Forwards: 50 User-Agent: call.center proxy Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 ------------------------------------------------------------------------ recv 1287 bytes from udp/[KAZOOIP]:5060 at 04:33:25.682876: ------------------------------------------------------------------------ REFER sip:888100@KAZOOIP:11000;transport=udp SIP/2.0 Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK4b2e.70b16b32b7c17b8954d52f73378b9395.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKSfzxBaEw;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net>;tag=8DpFtvUtv34cr CSeq: 11 REFER Call-ID: 08594CE6-59F94E9000060587-C1811700 Max-Forwards: 50 Refer-To: <sip:888701@pbxdg.domain.net;transport=tcp?Replaces=from-tag%3D2MmjJy6lx0AU9GCxUleos5IZYh1wnS1b%3Bh8f945jJkMIAobkKwGnAEa0QFY.J6bTm%3Bto-tag%3D594447DA-59F94E8500039E2C-9709B700&Require=replaces> Referred-By: <sip:user_f84u8dn62s@pbxdg.domain.net>;transport=tcp User-Agent: call.center proxy Contact: <sip:46.19.210.33:6050;transport=udp> Content-Length: 0 X-AUTH-IP: 46.19.210.33 X-AUTH-PORT: 6050 X-ecallmgr_Account-ID: 75c5b9a0047e65399de45f41258e38e4 X-ecallmgr_Authorizing-Type: device X-ecallmgr_Authorizing-ID: c04a2812eff90b41dd1282c4ffc03998 X-ecallmgr_Username: user_f84u8dn62s X-ecallmgr_Realm: pbxdg.domain.net X-ecallmgr_Account-Realm: pbxdg.domain.net X-ecallmgr_Account-Name: Dove Gospel - Global X-ecallmgr_Presence-ID: 888701@pbxdg.domain.net X-ecallmgr_Owner-ID: 9333eab27c60732f233e2b803e7c073b ------------------------------------------------------------------------ send 430 bytes to udp/[KAZOOIP]:5060 at 04:33:25.683064: ------------------------------------------------------------------------ SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP KAZOOIP;branch=z9hG4bK4b2e.70b16b32b7c17b8954d52f73378b9395.0 Via: SIP/2.0/UDP 46.19.210.33:6050;received=46.19.210.33;branch=z9hG4bKSfzxBaEw;rport=6050 From: <sip:user_f84u8dn62s@pbxdg.domain.net>;tag=7BF47C90-59F94E9000060583-C1811700 To: <sip:888100@pbxdg.domain.net>;tag=8DpFtvUtv34cr Call-ID: 08594CE6-59F94E9000060587-C1811700 CSeq: 11 REFER Content-Length: 0 ------------------------------------------------------------------------ But these packets are out of order. 12 comes in first, then 11. This presumably went through a proxy first. It would be interesting to see what the logs show in /var/log/kamailio/kamailio.log for this same Call-ID, 08594CE6-59F94E9000060587-C1811700 . Please include that, as it's probably the actual issue here. Quote
jlhughes Posted November 1, 2017 Author Report Posted November 1, 2017 It is a little bit beyond me, and I'm EXTREMELY appreciative for this help: Nov 1 04:33:20 pbx01 kamailio[1766]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received udp request INVITE sip:888100@pbxdg.domain.net:5060;transport=udp Nov 1 04:33:20 pbx01 kamailio[1766]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|source 46.19.210.33:6050 -> SERVERIP:5060 Nov 1 04:33:20 pbx01 kamailio[1766]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|from sip:user_f84u8dn62s@pbxdg.domain.net Nov 1 04:33:20 pbx01 kamailio[1766]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|to sip:888100@pbxdg.domain.net Nov 1 04:33:20 pbx01 kamailio[1766]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|originated from external sources Nov 1 04:33:20 pbx01 kamailio[1766]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|pass|SERVERIP:5060 -> SERVERIP:11000 Nov 1 04:33:20 pbx01 kamailio[1763]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received internal reply 100 Trying Nov 1 04:33:20 pbx01 kamailio[1763]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|source SERVERIP:11000 Nov 1 04:33:20 pbx01 kamailio[1763]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|pass|46.19.210.33:6050 Nov 1 04:33:20 pbx01 kamailio[1826]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|received dialog update for sip:888701@pbxdg.domain.net state confirmed from sip:SERVERIP:11000 at 1509510800/1509510800 Nov 1 04:33:20 pbx01 kamailio[1826]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|skip dialog update for sip:888701@pbxdg.domain.net Nov 1 04:33:20 pbx01 kamailio[1826]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|skip presence update for sip:888701@pbxdg.domain.net Nov 1 04:33:20 pbx01 kamailio[1826]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|finished processing dialog update for sip:888701@pbxdg.domain.net state confirmed from sip:SERVERIP:11000 at 1509510800/1509510800/1509510800 Nov 1 04:33:20 pbx01 kamailio[1769]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received internal reply 200 OK Nov 1 04:33:21 pbx01 kamailio[1769]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|source SERVERIP:11000 Nov 1 04:33:21 pbx01 kamailio[1769]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|call setup, now ignoring abnormal termination Nov 1 04:33:21 pbx01 kamailio[1769]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|pass|46.19.210.33:6050 Nov 1 04:33:21 pbx01 kamailio[1820]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|received dialog update for sip:888701@pbxdg.domain.net state confirmed from sip:SERVERIP:11000 at 1509510801/1509510801 Nov 1 04:33:21 pbx01 kamailio[1820]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|skip dialog update for sip:888701@pbxdg.domain.net Nov 1 04:33:21 pbx01 kamailio[1820]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|skip presence update for sip:888701@pbxdg.domain.net Nov 1 04:33:21 pbx01 kamailio[1820]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|finished processing dialog update for sip:888701@pbxdg.domain.net state confirmed from sip:SERVERIP:11000 at 1509510801/1509510801/1509510801 Nov 1 04:33:21 pbx01 kamailio[1760]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received udp request ACK sip:888100@SERVERIP:11000;transport=udp Nov 1 04:33:21 pbx01 kamailio[1760]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|source 46.19.210.33:6050 -> SERVERIP:5060 Nov 1 04:33:21 pbx01 kamailio[1760]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|from sip:user_f84u8dn62s@pbxdg.domain.net Nov 1 04:33:21 pbx01 kamailio[1760]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|to sip:888100@pbxdg.domain.net Nov 1 04:33:21 pbx01 kamailio[1760]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|originated from external sources Nov 1 04:33:21 pbx01 kamailio[1760]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|loose_route in-dialog message Nov 1 04:33:21 pbx01 kamailio[1760]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|pass|SERVERIP:5060 -> SERVERIP:11000 Nov 1 04:33:25 pbx01 kamailio[1774]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received udp request BYE sip:888100@SERVERIP:11000;transport=udp Nov 1 04:33:25 pbx01 kamailio[1762]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received udp request REFER sip:888100@SERVERIP:11000;transport=udp Nov 1 04:33:25 pbx01 kamailio[1774]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|source 46.19.210.33:6050 -> SERVERIP:5060 Nov 1 04:33:25 pbx01 kamailio[1774]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|from sip:user_f84u8dn62s@pbxdg.domain.net Nov 1 04:33:25 pbx01 kamailio[1774]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|to sip:888100@pbxdg.domain.net Nov 1 04:33:25 pbx01 kamailio[1762]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|source 46.19.210.33:6050 -> SERVERIP:5060 Nov 1 04:33:25 pbx01 kamailio[1762]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|from sip:user_f84u8dn62s@pbxdg.domain.net Nov 1 04:33:25 pbx01 kamailio[1762]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|to sip:888100@pbxdg.domain.net Nov 1 04:33:25 pbx01 kamailio[1774]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|originated from external sources Nov 1 04:33:25 pbx01 kamailio[1762]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|originated from external sources Nov 1 04:33:25 pbx01 kamailio[1774]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|loose_route in-dialog message Nov 1 04:33:25 pbx01 kamailio[1762]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|loose_route in-dialog message Nov 1 04:33:25 pbx01 kamailio[1774]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|pass|SERVERIP:5060 -> SERVERIP:11000 Nov 1 04:33:25 pbx01 kamailio[1762]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|pass|SERVERIP:5060 -> SERVERIP:11000 Nov 1 04:33:25 pbx01 kamailio[1771]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received internal reply 500 Internal Server Error Nov 1 04:33:25 pbx01 kamailio[1771]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|source SERVERIP:11000 Nov 1 04:33:25 pbx01 kamailio[1771]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received failure reply 500 <null> Nov 1 04:33:25 pbx01 kamailio[1771]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|pass|46.19.210.33:6050 Nov 1 04:33:25 pbx01 kamailio[1780]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received internal reply 200 OK Nov 1 04:33:25 pbx01 kamailio[1780]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|source SERVERIP:11000 Nov 1 04:33:25 pbx01 kamailio[1780]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|pass|46.19.210.33:6050 Nov 1 04:33:25 pbx01 kamailio[1815]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|received dialog update for sip:888701@pbxdg.domain.net state terminated from sip:SERVERIP:11000 at 1509510805/1509510805 Nov 1 04:33:25 pbx01 kamailio[1815]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|skip dialog update for sip:888701@pbxdg.domain.net Nov 1 04:33:25 pbx01 kamailio[1815]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|skip presence update for sip:888701@pbxdg.domain.net Nov 1 04:33:25 pbx01 kamailio[1815]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|log|finished processing dialog update for sip:888701@pbxdg.domain.net state terminated from sip:SERVERIP:11000 at 1509510805/1509510805/1509510805 Hoping this spreads some light on the issue Quote
Administrators Darren Schreiber Posted November 1, 2017 Administrators Report Posted November 1, 2017 Welp, looks like it's not Kamailio or Kazoo at all. Whatever is generating this: Nov 1 04:33:25 pbx01 kamailio[1774]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received udp request BYE sip:888100@SERVERIP:11000;transport=udp Nov 1 04:33:25 pbx01 kamailio[1762]: INFO: <script>: 08594CE6-59F94E9000060587-C1811700|start|received udp request REFER sip:888100@SERVERIP:11000;transport=udp Is broken. Who is the manufacturer of the phone or software generating these packets? Quote
jlhughes Posted November 1, 2017 Author Report Posted November 1, 2017 Welp! (hides under a rock), We are using DIDww's appliance software called Call.Center. This is purely due to the simplicity of the deployment onto both workstations and mobile devices, it is cloud based and all you have to do is provide either a barcode (to activate call.center) or a special key. And automatically the credentials and SIP server is managed through a website. On that note as well! when turning off the push feature, the calls route successfully and there is no issue at all. So it could actually be an issue with the push software they have engineered. Interesting huh! Quote
Administrators Darren Schreiber Posted November 1, 2017 Administrators Report Posted November 1, 2017 Yeah, you should ask them. We work with them a lot and never run into this before BUT we've also never used the feature you're using. Perhaps they don't like some response we're sending earlier in the transaction, but quite literally they, out-of-the-blue, just send a "BYE" and then a REFER. This is like hanging up the phone, then, while the phone is hungup, asking the remote party to transfer you. Obviously it's too late to talk to someone on the phone if you've already hung it up. Quote
jlhughes Posted November 1, 2017 Author Report Posted November 1, 2017 Darren, You are a gem! thanks so much for pointing me in the right direction. Interesting that you work with DIDww! as an internal telco for Dove Gospel - Global, we had used them for about 4 years until we migrated over to DIDx. The coverage there is pretty crazy! we get DIDs in Uganda lol. Quote
Administrators Darren Schreiber Posted November 1, 2017 Administrators Report Posted November 1, 2017 Well let's see what they say first before we celebrate. Quote
jlhughes Posted November 2, 2017 Author Report Posted November 2, 2017 19 hours ago, Darren Schreiber said: Well let's see what they say first before we celebrate. I have been in close communication with DIDww, and they have shared that they've accepted the fault and began an internal investigation. They also intend to build a 2600Hz instance and attempt to replicate the error. I would call that rather interesting of a response so far! Quote
jlhughes Posted November 4, 2017 Author Report Posted November 4, 2017 Quote Dear DG,Thank you for your update and provided all the details.Our engineers team detected possible cause of reported error andwe expect proxy server update coming next week.As soon as update will be released we will inform you. It's time to crack out the wine to celebrate Quote
Recommended Posts
Join the conversation
You can post now and register later. If you have an account, sign in now to post with your account.