Call Scenario Customer 9145100 calls dialplan 2000 that get transferred to Agent(4005) Agent 4005 originates a new call to 4007 placing 9145100 on hold While 4007 is ringing 4005 hangs up the phone 9145100 is bridged with 4007...the sip messages indicated that 4005 is talking to 4007 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.454167 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/9145100@10.47.32.159 [02d73189-6308-41ce-ac11-3e9e829c91c3] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.454167 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_NEW (Cur 1 Tot 6) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.454167 [DEBUG] sofia.c:9873 sofia/internal/9145100@10.47.32.159 receiving invite from 10.47.32.159:59063 version: 1.6.19 32bit 2018-01-30 15:20:42.454167 [DEBUG] sofia.c:9989 IP 10.47.32.159 Approved by acl "domains[]". Access Granted. 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] sofia.c:7084 Channel sofia/internal/9145100@10.47.32.159 entering state [received][100] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] sofia.c:7094 Remote SDP: 02d73189-6308-41ce-ac11-3e9e829c91c3 v=0 02d73189-6308-41ce-ac11-3e9e829c91c3 o=aastra400 1929707267 1929707267 IN IP4 10.47.32.159 02d73189-6308-41ce-ac11-3e9e829c91c3 s=call 02d73189-6308-41ce-ac11-3e9e829c91c3 c=IN IP4 10.47.26.150 02d73189-6308-41ce-ac11-3e9e829c91c3 t=0 0 02d73189-6308-41ce-ac11-3e9e829c91c3 m=audio 50376 RTP/AVP 102 0 8 18 121 101 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:102 G7221/16000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:102 bitrate=32000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:18 G729/8000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:18 annexb=no 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:121 L16/16000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:101 telephone-event/8000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:101 0-15 02d73189-6308-41ce-ac11-3e9e829c91c3 a=ptime:20 02d73189-6308-41ce-ac11-3e9e829c91c3 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] sofia.c:7486 (sofia/internal/9145100@10.47.32.159) State Change CS_NEW -> CS_INIT 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/9145100@10.47.32.159) State NEW 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_INIT (Cur 1 Tot 6) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/9145100@10.47.32.159) State INIT 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] mod_sofia.c:90 sofia/internal/9145100@10.47.32.159 SOFIA INIT 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:40 sofia/internal/9145100@10.47.32.159 Standard INIT 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/9145100@10.47.32.159) State Change CS_INIT -> CS_ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/9145100@10.47.32.159) State INIT going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_ROUTING (Cur 1 Tot 6) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_channel.c:2249 (sofia/internal/9145100@10.47.32.159) Callstate Change DOWN -> RINGING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/9145100@10.47.32.159) State ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] mod_sofia.c:143 sofia/internal/9145100@10.47.32.159 SOFIA ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:236 sofia/internal/9145100@10.47.32.159 Standard ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [INFO] mod_dialplan_xml.c:637 Processing IVR Team 3 5xxx <9145100>->2000 in context public 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 parsing [public->ca3964ea-2560-420e-9ad4-ae15696985ed] continue=false 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 Regex (FAIL) [ca3964ea-2560-420e-9ad4-ae15696985ed] destination_number(2000) =~ /2100/ break=on-false 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 parsing [public->cc8e1c31-cd14-47fb-a679-08c6c2fe33da] continue=false 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 Regex (PASS) [cc8e1c31-cd14-47fb-a679-08c6c2fe33da] destination_number(2000) =~ /2000/ break=on-false 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 Action ring_ready() 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 Action park() 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/9145100@10.47.32.159) State Change CS_ROUTING -> CS_EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/9145100@10.47.32.159) State ROUTING going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_EXECUTE (Cur 1 Tot 6) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/9145100@10.47.32.159) State EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] mod_sofia.c:198 sofia/internal/9145100@10.47.32.159 SOFIA EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.473667 [DEBUG] switch_core_state_machine.c:328 sofia/internal/9145100@10.47.32.159 Standard EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 ring_ready() ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:573 nua_stack_signal() nua(03A37510): recv signal r_respond 180 Ringing ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606A998, ...) called ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(041BA618) tpn = TCP/10.47.32.159:59063 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37510): sent signal r_respond 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.494666 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/internal/9145100@10.47.32.159! ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(041BA618): 799 bytes of 799 to tcp/10.47.32.159:59063 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 799 send 799 bytes to tcp/[10.47.32.159]:59063 at 20:20:42.494666: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/TCP 10.47.32.159;branch=z9hG4bK_AI2018Jan30204189200023;rport=59063 From: "IVR Team 3 5xxx" ;tag=AI2213AE6C7868B46B To: ;tag=KpSe5a4699cgQ Call-ID: AI79A7BDE8B4252507_00:08:5d:8d:5e:e0 CSeq: 1 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, 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 P-Asserted-Identity: "2000" ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2296 tport_set_secondary_timer() tport(041BA618): reset timer ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:6791 incoming_reply() nta: sent 180 Ringing for INVITE (1) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37510): call state changed: received -> early ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event i_state 180 Ringing 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.494666 [DEBUG] sofia.c:7084 Channel sofia/internal/9145100@10.47.32.159 entering state [early][180] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.494666 [NOTICE] mod_dptools.c:1028 Ring Ready sofia/internal/9145100@10.47.32.159! 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 park() 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.554668 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-IsACD=False) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-IsACD=False) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.554668 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-IsACD]=[False] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.574169 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(domain="d592d159-891a-4184-aa8f-e10995a4270c") 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(domain="d592d159-891a-4184-aa8f-e10995a4270c") 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.574169 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [domain]=["d592d159-891a-4184-aa8f-e10995a4270c"] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.614170 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(domain_name="d592d159-891a-4184-aa8f-e10995a4270c") 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(domain_name="d592d159-891a-4184-aa8f-e10995a4270c") 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.614170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [domain_name]=["d592d159-891a-4184-aa8f-e10995a4270c"] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/9145100@10.47.32.159 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_codec.c:111 sofia/internal/9145100@10.47.32.159 Original read codec set to PCMU:0 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:4767 sofia/internal/9145100@10.47.32.159 Set 2833 dtmf send payload to 101 recv payload to 101 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/9145100@10.47.32.159] 10.47.26.24 port 22272 -> 10.47.26.150 port 50376 codec: 0 ms: 20 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:7179 sofia/internal/9145100@10.47.32.159 Set 2833 dtmf send payload to 101 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:7186 sofia/internal/9145100@10.47.32.159 Set 2833 dtmf receive payload to 101 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [DEBUG] switch_core_media.c:7209 sofia/internal/9145100@10.47.32.159 Set rtp dtmf delay to 40 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.633669 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/9145100@10.47.32.159! 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.654168 [DEBUG] switch_channel.c:3474 (sofia/internal/9145100@10.47.32.159) Callstate Change RINGING -> EARLY 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.654168 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/9145100@10.47.32.159. 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.654168 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/9145100@10.47.32.159: 02d73189-6308-41ce-ac11-3e9e829c91c3 v=0 02d73189-6308-41ce-ac11-3e9e829c91c3 o=FreeSWITCH 1517321370 1517321371 IN IP4 10.47.26.24 02d73189-6308-41ce-ac11-3e9e829c91c3 s=FreeSWITCH 02d73189-6308-41ce-ac11-3e9e829c91c3 c=IN IP4 10.47.26.24 02d73189-6308-41ce-ac11-3e9e829c91c3 t=0 0 02d73189-6308-41ce-ac11-3e9e829c91c3 m=audio 22272 RTP/AVP 0 101 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:0 PCMU/8000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:101 telephone-event/8000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:101 0-16 02d73189-6308-41ce-ac11-3e9e829c91c3 a=ptime:20 02d73189-6308-41ce-ac11-3e9e829c91c3 a=sendrecv 02d73189-6308-41ce-ac11-3e9e829c91c3 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37510): sent signal r_respond ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:573 nua_stack_signal() nua(03A37510): recv signal r_respond 200 OK ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606A998, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0606A998, 00000000, 03D2848A, -1) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0606A998, 00000000, 03D2848A, -1) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1515 soa_generate_answer() soa_generate_answer(static::0606A998) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606A998, soa_generate_answer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1189 offer_answer_step() soa_static(0606A998, soa_generate_answer): generating local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1230 offer_answer_step() soa_static(0606A998, soa_generate_answer): upgrade with remote description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0552F930, 041F7B98, ""): called 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.654168 [NOTICE] mod_commands.c:3664 Channel [sofia/internal/9145100@10.47.32.159] has been answered ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1446 offer_answer_step() soa_static(0606A998, soa_generate_answer): storing local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::0606A998, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606A998, [00000000], [0552F958], [0552F94C]) called ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(041BA618) tpn = TCP/10.47.32.159:59063 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(041BA618): 1050 bytes of 1050 to tcp/10.47.32.159:59063 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 1050 send 1050 bytes to tcp/[10.47.32.159]:59063 at 20:20:42.655669: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.47.32.159;branch=z9hG4bK_AI2018Jan30204189200023;rport=59063 From: "IVR Team 3 5xxx" ;tag=AI2213AE6C7868B46B To: ;tag=KpSe5a4699cgQ Call-ID: AI79A7BDE8B4252507_00:08:5d:8d:5e:e0 CSeq: 1 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, 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: 218 P-Asserted-Identity: "2000" v=0 o=FreeSWITCH 1517321370 1517321371 IN IP4 10.47.26.24 s=FreeSWITCH c=IN IP4 10.47.26.24 t=0 0 m=audio 22272 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2296 tport_set_secondary_timer() tport(041BA618): reset timer ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:6791 incoming_reply() nta: sent 200 OK for INVITE (1) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 500 ms ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37510): call state changed: early -> completed, sent answer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606A998, [0552FA58], [0552FA4C], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:616 soa_get_params() soa_get_params(static::0606A998, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event i_state 200 OK 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.654168 [DEBUG] switch_channel.c:3773 (sofia/internal/9145100@10.47.32.159) Callstate Change EARLY -> ACTIVE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.654168 [DEBUG] sofia.c:7084 Channel sofia/internal/9145100@10.47.32.159 entering state [completed][200] ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608BEE8 from (udp/10.47.26.24:5060) has 411 bytes, veclen = 1 recv 411 bytes from udp/[10.47.32.159]:5060 at 20:20:42.667170: ------------------------------------------------------------------------ ACK sip:2000@10.47.26.24:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.32.159;branch=z9hG4bK_AI2018Jan302041289200024;rport To: sip:2000@10.47.26.24;tag=KpSe5a4699cgQ From: "IVR Team 3 5xxx" ;tag=AI2213AE6C7868B46B Call-ID: AI79A7BDE8B4252507_00:08:5d:8d:5e:e0 CSeq: 1 ACK Allow-Events: presence,dialog,message-summary,refer Max-Forwards: 70 User-Agent: Aastra 400 Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608BEE8 (411 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2880 agent_recv_request() nta: received ACK sip:2000@10.47.26.24:5060 SIP/2.0 (CSeq 1) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3019 agent_recv_request() nta: ACK (1) is going to INVITE (1) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0606A998) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event i_ack 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37510): call state changed: completed -> ready ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event i_state 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event i_active 200 Call active ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:5744 incoming_free() nta: incoming_free(063E5588) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2296 tport_set_secondary_timer() tport(041BA618): reset timer 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.673670 [DEBUG] sofia.c:7084 Channel sofia/internal/9145100@10.47.32.159 entering state [ready][200] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.753671 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Queue) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Queue) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.753671 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Queue] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.794172 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-MITEL-OverrideCallingDevice=) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-MITEL-OverrideCallingDevice=) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.794172 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-MITEL-OverrideCallingDevice]=[UNDEF] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.813671 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed. 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.834672 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-OverrideCalledDevice=2100) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-OverrideCalledDevice=2100) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.834672 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-OverrideCalledDevice]=[2100] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.854172 [DEBUG] switch_ivr.c:2165 (sofia/internal/9145100@10.47.32.159) State Change CS_EXECUTE -> CS_ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.854172 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/9145100@10.47.32.159 to XML[sofia/internal/2100@10.47.26.24@d592d159-891a-4184-aa8f-e10995a4270c] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/9145100@10.47.32.159) State EXECUTE going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_ROUTING (Cur 1 Tot 6) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_channel.c:2249 (sofia/internal/9145100@10.47.32.159) Callstate Change ACTIVE -> RINGING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/9145100@10.47.32.159) State ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] mod_sofia.c:143 sofia/internal/9145100@10.47.32.159 SOFIA ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_core_state_machine.c:236 sofia/internal/9145100@10.47.32.159 Standard ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [INFO] mod_dialplan_xml.c:637 Processing IVR Team 3 5xxx <9145100>->sofia/internal/2100@10.47.26.24 in context d592d159-891a-4184-aa8f-e10995a4270c 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 parsing [d592d159-891a-4184-aa8f-e10995a4270c->ca3964ea-2560-420e-9ad4-ae15696985ed] continue=false 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 Regex (PASS) [ca3964ea-2560-420e-9ad4-ae15696985ed] destination_number(sofia/internal/2100@10.47.26.24) =~ /2100/ break=on-false 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 Action export(hold_music=local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18) 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 Action park() 02d73189-6308-41ce-ac11-3e9e829c91c3 Dialplan: sofia/internal/9145100@10.47.32.159 Action playback(tone_stream://${ca-ring}) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/9145100@10.47.32.159) State Change CS_ROUTING -> CS_EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/9145100@10.47.32.159) State ROUTING going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_EXECUTE (Cur 1 Tot 6) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_channel.c:2251 (sofia/internal/9145100@10.47.32.159) Callstate Change RINGING -> ACTIVE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/9145100@10.47.32.159) State EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] mod_sofia.c:198 sofia/internal/9145100@10.47.32.159 SOFIA EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_core_state_machine.c:328 sofia/internal/9145100@10.47.32.159 Standard EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(hold_music=local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:42.873673 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [hold_music]=[local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18] 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 park() ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 9694 ms 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:43.253678 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-IsACD=True) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-IsACD=True) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:43.253678 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-IsACD]=[True] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:43.294178 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(hold_music=local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(hold_music=local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:43.294178 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [hold_music]=[local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.094688 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-OverrideCalledDevice=4005) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-OverrideCalledDevice=4005) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.094688 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-OverrideCalledDevice]=[4005] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.133689 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.133689 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Agent] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.173688 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-OverrideCalledDevice=4005) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-OverrideCalledDevice=4005) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.173688 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-OverrideCalledDevice]=[4005] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.234189 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(continue_on_fail=true) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(continue_on_fail=true) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.234189 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [continue_on_fail]=[true] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.274191 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(hangup_after_bridge=true) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(hangup_after_bridge=true) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.274191 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [hangup_after_bridge]=[true] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.314692 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(transfer_ringback=tone_stream://${ca-ring};loops=-1) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(transfer_ringback=tone_stream://%(2000,4000,440,480);loops=-1) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.314692 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [transfer_ringback]=[tone_stream://%(2000,4000,440,480);loops=-1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute bridge([origination_uuid=d04f17c2-8f05-4791-acff-9272b4922032 ] sofia/internal/sip:4005@10.47.32.159) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 bridge([origination_uuid=d04f17c2-8f05-4791-acff-9272b4922032 ] sofia/internal/sip:4005@10.47.32.159) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1823 (sofia/internal/9145100@10.47.32.159) Callstate Change ACTIVE -> RING_WAIT 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [X-Mitel-IsACD]=[True] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [domain]=["d592d159-891a-4184-aa8f-e10995a4270c"] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [domain_name]=["d592d159-891a-4184-aa8f-e10995a4270c"] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [X-Mitel-CALLEDDEVICETYPE]=[Agent] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [X-Mitel-OverrideCalledDevice]=[4005] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [hold_music]=[local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [X-Mitel-IsACD]=[True] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [hold_music]=[local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [X-Mitel-OverrideCalledDevice]=[4005] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [X-Mitel-CALLEDDEVICETYPE]=[Agent] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [X-Mitel-OverrideCalledDevice]=[4005] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [continue_on_fail]=[true] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [hangup_after_bridge]=[true] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_channel.c:1250 sofia/internal/9145100@10.47.32.159 EXPORTING[export_vars] [transfer_ringback]=[tone_stream://%(2000,4000,440,480);loops=-1] to event 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:44.774197 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/4005@10.47.32.159 [d04f17c2-8f05-4791-acff-9272b4922032] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] mod_sofia.c:4819 (sofia/internal/4005@10.47.32.159) State Change CS_NEW -> CS_INIT d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_session.c:615 sofia/internal/4005@10.47.32.159 set UUID=d04f17c2-8f05-4791-acff-9272b4922032 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4005@10.47.32.159) Running State Change CS_INIT (Cur 2 Tot 7) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/4005@10.47.32.159) State INIT d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] mod_sofia.c:90 sofia/internal/4005@10.47.32.159 SOFIA INIT d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] sofia_glue.c:1295 sofia/internal/4005@10.47.32.159 sending invite version: 1.6.19 32bit d04f17c2-8f05-4791-acff-9272b4922032 Local SDP: d04f17c2-8f05-4791-acff-9272b4922032 v=0 d04f17c2-8f05-4791-acff-9272b4922032 o=FreeSWITCH 1517317846 1517317847 IN IP4 10.47.26.24 d04f17c2-8f05-4791-acff-9272b4922032 s=FreeSWITCH d04f17c2-8f05-4791-acff-9272b4922032 c=IN IP4 10.47.26.24 d04f17c2-8f05-4791-acff-9272b4922032 t=0 0 d04f17c2-8f05-4791-acff-9272b4922032 m=audio 25798 RTP/AVP 0 102 9 8 3 101 13 103 104 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:0 PCMU/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:102 opus/48000/2 d04f17c2-8f05-4791-acff-9272b4922032 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:9 G722/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:8 PCMA/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:3 GSM/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:101 telephone-event/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=fmtp:101 0-16 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:103 telephone-event/48000 d04f17c2-8f05-4791-acff-9272b4922032 a=fmtp:103 0-16 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:13 CN/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:104 CN/48000 d04f17c2-8f05-4791-acff-9272b4922032 a=ptime:20 d04f17c2-8f05-4791-acff-9272b4922032 a=sendrecv d04f17c2-8f05-4791-acff-9272b4922032 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37C18): sent signal r_invite ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37C18): recv signal r_invite d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:40 sofia/internal/4005@10.47.32.159 Standard INIT d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/4005@10.47.32.159) State Change CS_INIT -> CS_ROUTING ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:280 soa_clone() soa_clone(static::041B3D50, 03C2DCB0, 03A37C18) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606AC08, ...) called d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/4005@10.47.32.159) State INIT going to sleep ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606AC08, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0606AC08, 00000000, 06091EC3, -1) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0606AC08, 00000000, 06091EC3, -1) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_dialog.c:338 nua_dialog_usage_add() nua(03A37C18): adding session usage ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(06068648) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0606AC08) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1426 soa_generate_offer() soa_generate_offer(static::0606AC08, 0) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606AC08, soa_generate_offer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1189 offer_answer_step() soa_static(0606AC08, soa_generate_offer): generating local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1217 offer_answer_step() soa_static(0606AC08, soa_generate_offer): upgrade with local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0552F8F0, 00000000, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1446 offer_answer_step() soa_static(0606AC08, soa_generate_offer): storing local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606AC08, [00000000], [0552F91C], [0552F910]) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(03D83988) tpn = */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.47.32.159:5060 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4005@10.47.32.159) Running State Change CS_ROUTING (Cur 2 Tot 7) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(03D83988): not found by name */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(03D83988): 1438 bytes of 1438 to udp/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 1438 send 1438 bytes to udp/[10.47.32.159]:5060 at 20:20:44.780196: ------------------------------------------------------------------------ INVITE sip:4005@10.47.32.159 SIP/2.0 Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bK57rXt6FrtrmcD Max-Forwards: 22 From: "IVR Team 3 5xxx" ;tag=mZj765ma7j32j To: Call-ID: e45daeec-809d-1236-4794-3bb0e46905d4 CSeq: 118335758 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, 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 Privacy: none Content-Type: application/sdp Content-Disposition: session Content-Length: 539 X-FS-Support: update_display,send_info P-Asserted-Identity: "IVR Team 3 5xxx" v=0 o=FreeSWITCH 1517317846 1517317847 IN IP4 10.47.26.24 s=FreeSWITCH c=IN IP4 10.47.26.24 t=0 0 m=audio 25798 RTP/AVP 0 102 9 8 3 101 13 103 104 a=rtpmap:0 PCMU/8000 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtpmap:104 CN/48000 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/4005@10.47.32.159) State ROUTING a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent INVITE (118335758) to */10.47.32.159:5060 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] mod_sofia.c:143 sofia/internal/4005@10.47.32.159 SOFIA ROUTING ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(03D83988): pending 0608CBD8 for udp/10.47.26.24:5060 (already 0) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/4005@10.47.32.159) State Change CS_ROUTING -> CS_CONSUME_MEDIA ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/4005@10.47.32.159) State ROUTING going to sleep ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37C18): call state changed: init -> calling, sent offer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606AC08, [0552F930], [0552F924], [00000000]) called d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4005@10.47.32.159) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 7) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:269 nua_stack_event() nua(03A37C18): event i_state INVITE sent d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] sofia.c:7084 Channel sofia/internal/4005@10.47.32.159 entering state [calling][0] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/4005@10.47.32.159) State CONSUME_MEDIA d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:44.774197 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/4005@10.47.32.159) State CONSUME_MEDIA going to sleep ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608DAF0 from (udp/10.47.26.24:5060) has 274 bytes, veclen = 1 recv 274 bytes from udp/[10.47.32.159]:5060 at 20:20:44.782697: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bK57rXt6FrtrmcD To: From: "IVR Team 3 5xxx" ;tag=mZj765ma7j32j Call-ID: e45daeec-809d-1236-4794-3bb0e46905d4 CSeq: 118335758 INVITE Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608DAF0 (274 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (118335758) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 2.501 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608CBD8 by 03BEB208 with 0608DAF0 (preliminary) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608BA98 from (udp/10.47.26.24:5060) has 525 bytes, veclen = 1 recv 525 bytes from udp/[10.47.32.159]:5060 at 20:20:45.049700: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.47.26.24;rport=5060;branch=z9hG4bK57rXt6FrtrmcD;received=10.47.26.24 To: ;tag=AI0F169B6F656BA16E From: "IVR Team 3 5xxx" ;tag=mZj765ma7j32j Call-ID: e45daeec-809d-1236-4794-3bb0e46905d4 CSeq: 118335758 INVITE Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,PUBLISH,UPDATE,REFER,SUBSCRIBE User-Agent: Aastra 400 P-Asserted-Identity: "Mario Lemieux" Contact: Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608BA98 (525 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (118335758) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608CBD8 by 03BEB208 with 0608BA98 (preliminary) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event r_invite 180 Ringing ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37C18): call state changed: calling -> proceeding ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event i_state 180 Ringing 2018-01-30 15:20:45.034201 [INFO] sofia.c:1279 sofia/internal/4005@10.47.32.159 Update Callee ID to "Mario Lemieux" <4005> d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:45.053701 [DEBUG] sofia.c:7084 Channel sofia/internal/4005@10.47.32.159 entering state [proceeding][180] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:45.053701 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/4005@10.47.32.159! d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:45.053701 [DEBUG] switch_channel.c:3346 (sofia/internal/4005@10.47.32.159) Callstate Change DOWN -> RINGING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:45.093701 [DEBUG] switch_ivr_originate.c:1273 Raw Codec Activation Success L16@8000hz 1 channel 20ms 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:45.093701 [DEBUG] switch_core_codec.c:223 sofia/internal/9145100@10.47.32.159 Push codec L16:100 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:45.093701 [DEBUG] switch_ivr_originate.c:1305 Play Ringback File [tone_stream://%(2000,4000,440,480);loops=-1] ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 7070 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608DF40 from (udp/10.47.26.24:5060) has 892 bytes, veclen = 1 recv 892 bytes from udp/[10.47.32.159]:5060 at 20:20:47.104225: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.47.26.24;rport=5060;branch=z9hG4bK57rXt6FrtrmcD;received=10.47.26.24 To: ;tag=AI0F169B6F656BA16E From: "IVR Team 3 5xxx" ;tag=mZj765ma7j32j Call-ID: e45daeec-809d-1236-4794-3bb0e46905d4 CSeq: 118335758 INVITE Allow-Events: presence,dialog,message-summary,refer Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,PUBLISH,UPDATE,REFER,SUBSCRIBE User-Agent: Aastra 400 P-Asserted-Identity: "Mario Lemieux" Content-Type: application/sdp Contact: Content-Length: 286 v=0 o=aastra400 1179391925 1179391925 IN IP4 10.47.32.159 s=call c=IN IP4 10.33.28.81 t=0 0 m=audio 3000 RTP/AVP 0 9 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=silenceSupp:off - - - - ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608DF40 (892 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (118335758) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608CBD8 by 03BEB208 with 0608DF40 ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0606AC08, 00000000, 063B9AC6, 286) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1595 soa_process_answer() soa_process_answer(static::0606AC08) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606AC08, soa_process_answer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(063F40B0, 060928C8, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1304 offer_answer_step() soa_static(0606AC08, soa_process_answer): upgrade codecs with remote description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1446 offer_answer_step() soa_static(0606AC08, soa_process_answer): storing local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::0606AC08, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:988 nua_session_client_response() nua(03A37C18): INVITE: processed SDP answer in 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event r_invite 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37C18): call state changed: proceeding -> completing, received answer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0606AC08, [0552F5B0], [0552F5A4], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:616 soa_get_params() soa_get_params(static::0606AC08, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event i_state 200 OK d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] sofia.c:7084 Channel sofia/internal/4005@10.47.32.159 entering state [completing][200] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] sofia.c:7094 Remote SDP: d04f17c2-8f05-4791-acff-9272b4922032 v=0 d04f17c2-8f05-4791-acff-9272b4922032 o=aastra400 1179391925 1179391925 IN IP4 10.47.32.159 d04f17c2-8f05-4791-acff-9272b4922032 s=call d04f17c2-8f05-4791-acff-9272b4922032 c=IN IP4 10.33.28.81 d04f17c2-8f05-4791-acff-9272b4922032 t=0 0 d04f17c2-8f05-4791-acff-9272b4922032 m=audio 3000 RTP/AVP 0 9 8 101 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:0 PCMU/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:9 G722/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:8 PCMA/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:101 telephone-event/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=fmtp:101 0-15 d04f17c2-8f05-4791-acff-9272b4922032 a=ptime:20 d04f17c2-8f05-4791-acff-9272b4922032 a=silenceSupp:off - - - - d04f17c2-8f05-4791-acff-9272b4922032 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37C18): sent signal r_ack ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37C18): recv signal r_ack ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606AC08, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::0606AC08, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(03D83988) tpn = */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(03D83988): not found by name */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(03D83988): 375 bytes of 375 to udp/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 375 send 375 bytes to udp/[10.47.32.159]:5060 at 20:20:47.114727: ------------------------------------------------------------------------ ACK sip:4005@10.47.32.159:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bK6gjpv10UQ1aZr Max-Forwards: 70 From: "IVR Team 3 5xxx" ;tag=mZj765ma7j32j To: ;tag=AI0F169B6F656BA16E Call-ID: e45daeec-809d-1236-4794-3bb0e46905d4 CSeq: 118335758 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent ACK (118335758) to */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37C18): call state changed: completing -> ready ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event i_state 200 ACK sent ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event i_active 200 Call active d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] sofia.c:7084 Channel sofia/internal/4005@10.47.32.159 entering state [ready][200] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/4005@10.47.32.159 PCMU/8000 20 ms 160 samples 64000 bits 1 channels d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_codec.c:111 sofia/internal/4005@10.47.32.159 Original read codec set to PCMU:0 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:4767 sofia/internal/4005@10.47.32.159 Set 2833 dtmf send payload to 101 recv payload to 101 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/4005@10.47.32.159] 10.47.26.24 port 25798 -> 10.33.28.81 port 3000 codec: 0 ms: 20 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:7179 sofia/internal/4005@10.47.32.159 Set 2833 dtmf send payload to 101 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:7186 sofia/internal/4005@10.47.32.159 Set 2833 dtmf receive payload to 101 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_core_media.c:7209 sofia/internal/4005@10.47.32.159 Set rtp dtmf delay to 40 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [NOTICE] sofia.c:8218 Channel [sofia/internal/4005@10.47.32.159] has been answered d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.113727 [DEBUG] switch_channel.c:3773 (sofia/internal/4005@10.47.32.159) Callstate Change RINGING -> ACTIVE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.134227 [DEBUG] switch_core_codec.c:248 sofia/internal/9145100@10.47.32.159 Restore previous codec PCMU:0. 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.134227 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/internal/4005@10.47.32.159] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.134227 [DEBUG] switch_channel.c:2047 (sofia/internal/9145100@10.47.32.159) Callstate Change RING_WAIT -> ACTIVE d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.134227 [DEBUG] switch_ivr.c:623 sofia/internal/4005@10.47.32.159 Command Execute export(hold_music=local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18) d04f17c2-8f05-4791-acff-9272b4922032 EXECUTE sofia/internal/4005@10.47.32.159 export(hold_music=local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.134227 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [hold_music]=[local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.134227 [DEBUG] switch_ivr_bridge.c:1614 (sofia/internal/4005@10.47.32.159) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.134227 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4005@10.47.32.159) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 7) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.134227 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/4005@10.47.32.159) State EXCHANGE_MEDIA d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.134227 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37C18): sent signal r_update ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37C18): recv signal r_update ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606AC08, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0606AC08) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1426 soa_generate_offer() soa_generate_offer(static::0606AC08, 0) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606AC08, soa_generate_offer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(063F5AF0, 00000000, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606AC08, [00000000], [0552F948], [0552F93C]) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(03D83988) tpn = */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(03D83988): not found by name */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(03D83988): 1240 bytes of 1240 to udp/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 1240 send 1240 bytes to udp/[10.47.32.159]:5060 at 20:20:47.142227: ------------------------------------------------------------------------ UPDATE sip:4005@10.47.32.159:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bK7SBFyvHZma1Hm Max-Forwards: 70 From: "IVR Team 3 5xxx" ;tag=mZj765ma7j32j To: ;tag=AI0F169B6F656BA16E Call-ID: e45daeec-809d-1236-4794-3bb0e46905d4 CSeq: 118335759 UPDATE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 539 P-Asserted-Identity: "IVR Team 3 5xxx" v=0 o=FreeSWITCH 1517317846 1517317847 IN IP4 10.47.26.24 s=FreeSWITCH c=IN IP4 10.47.26.24 t=0 0 m=audio 25798 RTP/AVP 0 9 8 101 102 3 13 103 104 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:3 GSM/8000 a=rtpmap:13 CN/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtpmap:104 CN/48000 a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent UPDATE (118335759) to */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(03D83988): pending 0608DAF0 for udp/10.47.26.24:5060 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4145 signal_call_state_change() nua(03A37C18): ready call updated: calling sent offer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606AC08, [0552F95C], [0552F950], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:269 nua_stack_event() nua(03A37C18): event i_state UPDATE sent ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608BA98 from (udp/10.47.26.24:5060) has 892 bytes, veclen = 1 recv 892 bytes from udp/[10.47.32.159]:5060 at 20:20:47.152226: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.47.26.24;rport=5060;branch=z9hG4bK7SBFyvHZma1Hm;received=10.47.26.24 To: ;tag=AI0F169B6F656BA16E From: "IVR Team 3 5xxx" ;tag=mZj765ma7j32j Call-ID: e45daeec-809d-1236-4794-3bb0e46905d4 CSeq: 118335759 UPDATE Contact: Allow-Events: presence,dialog,message-summary,refer Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,PUBLISH,UPDATE,REFER,SUBSCRIBE User-Agent: Aastra 400 P-Asserted-Identity: "Mario Lemieux" Content-Type: application/sdp Content-Length: 286 v=0 o=aastra400 1179391925 1179391926 IN IP4 10.47.32.159 s=call c=IN IP4 10.33.28.81 t=0 0 m=audio 3000 RTP/AVP 0 9 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=silenceSupp:off - - - - ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608BA98 (892 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for UPDATE (118335759) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 10.999 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608DAF0 by 063E4648 with 0608BA98 ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0606AC08, 00000000, 063BA61E, 286) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1595 soa_process_answer() soa_process_answer(static::0606AC08) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606AC08, soa_process_answer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(063F5AF0, 093E49F0, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1304 offer_answer_step() soa_static(0606AC08, soa_process_answer): upgrade codecs with remote description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::0606AC08, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:988 nua_session_client_response() nua(03A37C18): UPDATE: processed SDP answer in 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event r_update 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4145 signal_call_state_change() nua(03A37C18): ready call updated: ready received answer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0606AC08, [0552F5EC], [0552F5E0], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:616 soa_get_params() soa_get_params(static::0606AC08, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event i_state 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event i_active 200 Call active d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] sofia.c:7084 Channel sofia/internal/4005@10.47.32.159 entering state [calling][0] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] sofia.c:7084 Channel sofia/internal/4005@10.47.32.159 entering state [ready][200] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] sofia.c:7094 Remote SDP: d04f17c2-8f05-4791-acff-9272b4922032 v=0 d04f17c2-8f05-4791-acff-9272b4922032 o=aastra400 1179391925 1179391926 IN IP4 10.47.32.159 d04f17c2-8f05-4791-acff-9272b4922032 s=call d04f17c2-8f05-4791-acff-9272b4922032 c=IN IP4 10.33.28.81 d04f17c2-8f05-4791-acff-9272b4922032 t=0 0 d04f17c2-8f05-4791-acff-9272b4922032 m=audio 3000 RTP/AVP 0 9 8 101 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:0 PCMU/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:9 G722/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:8 PCMA/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=rtpmap:101 telephone-event/8000 d04f17c2-8f05-4791-acff-9272b4922032 a=fmtp:101 0-15 d04f17c2-8f05-4791-acff-9272b4922032 a=ptime:20 d04f17c2-8f05-4791-acff-9272b4922032 a=silenceSupp:off - - - - d04f17c2-8f05-4791-acff-9272b4922032 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:4767 sofia/internal/4005@10.47.32.159 Set 2833 dtmf send payload to 101 recv payload to 101 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37510): sent signal r_update ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37510): recv signal r_update ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606A998, ...) called d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] sofia.c:8061 Processing updated SDP ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0606A998) called d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.153727 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/4005@10.47.32.159. ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1426 soa_generate_offer() soa_generate_offer(static::0606A998, 0) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606A998, soa_generate_offer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0646AFE8, 00000000, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606A998, [00000000], [0552F948], [0552F93C]) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(03D83988) tpn = */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(03D83988): not found by name */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(03D83988): 926 bytes of 926 to udp/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 926 send 926 bytes to udp/[10.47.32.159]:5060 at 20:20:47.155727: ------------------------------------------------------------------------ UPDATE sip:9145100@10.47.32.159:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bK8247ZQ22HKQ4F Max-Forwards: 70 From: ;tag=KpSe5a4699cgQ To: "IVR Team 3 5xxx" ;tag=AI2213AE6C7868B46B Call-ID: AI79A7BDE8B4252507_00:08:5d:8d:5e:e0 CSeq: 118335759 UPDATE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 218 P-Asserted-Identity: "Mario Lemieux" v=0 o=FreeSWITCH 1517321370 1517321371 IN IP4 10.47.26.24 s=FreeSWITCH c=IN IP4 10.47.26.24 t=0 0 m=audio 22272 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent UPDATE (118335759) to */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(03D83988): pending 0608C110 for udp/10.47.26.24:5060 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4145 signal_call_state_change() nua(03A37510): ready call updated: calling sent offer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606A998, [0552F95C], [0552F950], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:269 nua_stack_event() nua(03A37510): event i_state UPDATE sent ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608D478 from (udp/10.47.26.24:5060) has 938 bytes, veclen = 1 recv 938 bytes from udp/[10.47.32.159]:5060 at 20:20:47.163228: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.47.26.24;rport=5060;branch=z9hG4bK8247ZQ22HKQ4F;received=10.47.26.24 To: "IVR Team 3 5xxx" ;tag=AI2213AE6C7868B46B From: ;tag=KpSe5a4699cgQ Call-ID: AI79A7BDE8B4252507_00:08:5d:8d:5e:e0 CSeq: 118335759 UPDATE Contact: Allow-Events: presence,dialog,message-summary,refer Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,PUBLISH,UPDATE,REFER,SUBSCRIBE User-Agent: Aastra 400 P-Asserted-Identity: "IVR Team 3 5xxx" Content-Type: application/sdp Content-Length: 324 v=0 o=aastra400 1929707267 1929707268 IN IP4 10.47.32.159 s=call c=IN IP4 10.47.26.150 t=0 0 m=audio 50376 RTP/AVP 102 0 8 18 121 101 a=rtpmap:102 G7221/16000 a=fmtp:102 bitrate=32000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:121 L16/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608D478 (938 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for UPDATE (118335759) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 8.501 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608C110 by 063E40D8 with 0608D478 ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0606A998, 00000000, 063DCFD6, 324) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1595 soa_process_answer() soa_process_answer(static::0606A998) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606A998, soa_process_answer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0646AFE8, 041F85B8, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1304 offer_answer_step() soa_static(0606A998, soa_process_answer): upgrade codecs with remote description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::0606A998, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:988 nua_session_client_response() nua(03A37510): UPDATE: processed SDP answer in 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event r_update 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4145 signal_call_state_change() nua(03A37510): ready call updated: ready received answer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0606A998, [0552F5EC], [0552F5E0], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:616 soa_get_params() soa_get_params(static::0606A998, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event i_state 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event i_active 200 Call active d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.174227 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed. 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] sofia.c:7084 Channel sofia/internal/9145100@10.47.32.159 entering state [calling][0] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] sofia.c:7084 Channel sofia/internal/9145100@10.47.32.159 entering state [ready][200] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] sofia.c:7094 Remote SDP: 02d73189-6308-41ce-ac11-3e9e829c91c3 v=0 02d73189-6308-41ce-ac11-3e9e829c91c3 o=aastra400 1929707267 1929707268 IN IP4 10.47.32.159 02d73189-6308-41ce-ac11-3e9e829c91c3 s=call 02d73189-6308-41ce-ac11-3e9e829c91c3 c=IN IP4 10.47.26.150 02d73189-6308-41ce-ac11-3e9e829c91c3 t=0 0 02d73189-6308-41ce-ac11-3e9e829c91c3 m=audio 50376 RTP/AVP 102 0 8 18 121 101 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:102 G7221/16000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:102 bitrate=32000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:18 G729/8000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:18 annexb=no 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:121 L16/16000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:101 telephone-event/8000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:101 0-15 02d73189-6308-41ce-ac11-3e9e829c91c3 a=ptime:20 02d73189-6308-41ce-ac11-3e9e829c91c3 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:4767 sofia/internal/9145100@10.47.32.159 Set 2833 dtmf send payload to 101 recv payload to 101 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] sofia.c:8061 Processing updated SDP 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.174227 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/9145100@10.47.32.159. 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.354230 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-ISINITIALDIRECTIONOUTBOUND=false) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-ISINITIALDIRECTIONOUTBOUND=false) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.354230 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-ISINITIALDIRECTIONOUTBOUND]=[false] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.374229 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CallState=UNHELD) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CallState=UNHELD) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.374229 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CallState]=[UNHELD] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.413730 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:20:47.413730 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Agent] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.453731 [DEBUG] switch_ivr.c:623 sofia/internal/4005@10.47.32.159 Command Execute export(X-Mitel-CallState=UNHELD) d04f17c2-8f05-4791-acff-9272b4922032 EXECUTE sofia/internal/4005@10.47.32.159 export(X-Mitel-CallState=UNHELD) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.453731 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CallState]=[UNHELD] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.893737 [DEBUG] switch_ivr.c:623 sofia/internal/4005@10.47.32.159 Command Execute speak(unimrcp|Samantha|2100) d04f17c2-8f05-4791-acff-9272b4922032 EXECUTE sofia/internal/4005@10.47.32.159 speak(unimrcp|Samantha|2100) 2018-01-30 15:20:47.893737 [INFO] mod_unimrcp.c:1624 speech_handle: name = unimrcp, rate = 8000, speed = 0, samples = 160, voice = , engine = unimrcp, param = (null) 2018-01-30 15:20:47.893737 [INFO] mod_unimrcp.c:1627 voice = Samantha, rate = 8000 2018-01-30 15:20:47.893737 [DEBUG] mod_unimrcp.c:683 (TTS-2) audio queue created 2018-01-30 15:20:47.893737 [NOTICE] mrcp_application.c:96 (TTS-2) Create MRCP Handle 0x94050d0 [nuance-profile] 2018-01-30 15:20:47.893737 [INFO] mrcp_client_session.c:133 (TTS-2) Create Channel TTS-2 2018-01-30 15:20:47.893737 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x9451140;4;0] 2018-01-30 15:20:47.893737 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x9451140;4;0] 2018-01-30 15:20:47.893737 [INFO] mrcp_client_session.c:387 (TTS-2) Receive App Request TTS-2 [2] 2018-01-30 15:20:47.893737 [WARNING] mrcp_client_session.c:1269 (TTS-2) Failed to Create Session TTS-2 [2] 2018-01-30 15:20:47.893737 [INFO] mrcp_client_session.c:533 (TTS-2) Raise App Response TTS-2 [2] FAILURE [1] 2018-01-30 15:20:47.893737 [ERR] mod_unimrcp.c:1913 (TTS-2) SYNTHESIZER channel error! 2018-01-30 15:20:47.893737 [DEBUG] mod_unimrcp.c:1577 (TTS-2) CLOSED ==> ERROR 2018-01-30 15:20:47.893737 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client] 2018-01-30 15:20:47.893737 [DEBUG] mod_unimrcp.c:1061 (TTS-2) Terminating MRCP session 2018-01-30 15:20:47.893737 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x9451880;4;0] 2018-01-30 15:20:47.893737 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x9451880;4;0] 2018-01-30 15:20:47.893737 [INFO] mrcp_client_session.c:387 (TTS-2) Receive App Request TTS-2 [1] 2018-01-30 15:20:47.893737 [INFO] mrcp_client_session.c:455 (TTS-2) Raise App Response TTS-2 [1] SUCCESS [0] 2018-01-30 15:20:47.893737 [DEBUG] mod_unimrcp.c:1828 (TTS-2) Destroying MRCP session 2018-01-30 15:20:47.893737 [NOTICE] mrcp_application.c:182 (TTS-2) Destroy MRCP Handle TTS-2 2018-01-30 15:20:47.893737 [DEBUG] mod_unimrcp.c:1577 (TTS-2) ERROR ==> CLOSED 2018-01-30 15:20:47.893737 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.893737 [ERR] switch_ivr_play_say.c:3008 Invalid TTS module! d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.954238 [DEBUG] switch_ivr.c:623 sofia/internal/4005@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Agent) d04f17c2-8f05-4791-acff-9272b4922032 EXECUTE sofia/internal/4005@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Agent) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:20:47.954238 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Agent] ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 4010 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate UPDATE (118335759) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/4 term, 1/6 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 10 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate UPDATE (118335759) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/3 term, 1/5 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 687 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer D fired, terminate INVITE (118335744) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/2 term, 1/4 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 12 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8982 outgoing_timer_bf() nta: timer F fired, terminating ACK (118335744) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/2 tout, 0/1 term, 1/3 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 1754 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all(00000000, 00000000, 0552FAD4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/3 term, 1/3 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 801 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all(00000000, 00000000, 0552FAD4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 9277 ms 2018-01-30 15:21:03.073448 [WARNING] switch_core_file.c:360 File has 2 channels, muxing to 1 channel will occur. ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all(00000000, 00000000, 0552FAD4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 14408 ms d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:06.593992 [DEBUG] switch_ivr.c:623 sofia/internal/4005@10.47.32.159 Command Execute set_profile_var(caller_id_number=4005) d04f17c2-8f05-4791-acff-9272b4922032 EXECUTE sofia/internal/4005@10.47.32.159 set_profile_var(caller_id_number=4005) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:06.633992 [DEBUG] switch_ivr.c:623 sofia/internal/4005@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Agent) d04f17c2-8f05-4791-acff-9272b4922032 EXECUTE sofia/internal/4005@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Agent) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:06.633992 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Agent] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.133499 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.133499 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Agent] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.273999 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CallState=HOLD) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CallState=HOLD) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.273999 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CallState]=[HOLD] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.333501 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.333501 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Agent] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.373502 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-HoldingDevice=4005) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-HoldingDevice=4005) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.373502 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-HoldingDevice]=[4005] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.394002 [DEBUG] switch_ivr.c:2165 (sofia/internal/4005@10.47.32.159) State Change CS_EXCHANGE_MEDIA -> CS_ROUTING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.394002 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/4005@10.47.32.159 to inline[park@public] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.394002 [DEBUG] switch_ivr.c:2165 (sofia/internal/9145100@10.47.32.159) State Change CS_EXECUTE -> CS_ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.394002 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/9145100@10.47.32.159 to inline[park@public] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/9145100@10.47.32.159 ending bridge by request from write function d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/4005@10.47.32.159] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/9145100@10.47.32.159] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/4005@10.47.32.159) State EXCHANGE_MEDIA going to sleep d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4005@10.47.32.159) Running State Change CS_ROUTING (Cur 2 Tot 7) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/4005@10.47.32.159) State ROUTING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] mod_sofia.c:143 sofia/internal/4005@10.47.32.159 SOFIA ROUTING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:236 sofia/internal/4005@10.47.32.159 Standard ROUTING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [INFO] switch_channel.c:3129 sofia/internal/4005@10.47.32.159 Flipping CID from "IVR Team 3 5xxx" <4005> to "Mario Lemieux" <4005> d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/4005@10.47.32.159) State Change CS_ROUTING -> CS_EXECUTE d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/4005@10.47.32.159) State ROUTING going to sleep d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4005@10.47.32.159) Running State Change CS_EXECUTE (Cur 2 Tot 7) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/4005@10.47.32.159) State EXECUTE d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] mod_sofia.c:198 sofia/internal/4005@10.47.32.159 SOFIA EXECUTE d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:328 sofia/internal/4005@10.47.32.159 Standard EXECUTE d04f17c2-8f05-4791-acff-9272b4922032 EXECUTE sofia/internal/4005@10.47.32.159 park() 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/9145100@10.47.32.159) State EXECUTE going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_ROUTING (Cur 2 Tot 7) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_channel.c:2249 (sofia/internal/9145100@10.47.32.159) Callstate Change ACTIVE -> RINGING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/9145100@10.47.32.159) State ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] mod_sofia.c:143 sofia/internal/9145100@10.47.32.159 SOFIA ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:236 sofia/internal/9145100@10.47.32.159 Standard ROUTING 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/9145100@10.47.32.159) State Change CS_ROUTING -> CS_EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/9145100@10.47.32.159) State ROUTING going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_EXECUTE (Cur 2 Tot 7) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_channel.c:2251 (sofia/internal/9145100@10.47.32.159) Callstate Change RINGING -> ACTIVE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/9145100@10.47.32.159) State EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] mod_sofia.c:198 sofia/internal/9145100@10.47.32.159 SOFIA EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.414001 [DEBUG] switch_core_state_machine.c:328 sofia/internal/9145100@10.47.32.159 Standard EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 park() 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.753507 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute playback(${hold_music}) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 playback(local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18) 2018-01-30 15:21:07.753507 [DEBUG] mod_local_stream.c:871 Opening Stream [74cefb6e-becb-4316-8c75-3042dfdd1f18] 8000hz 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:07.753507 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.834007 [DEBUG] switch_ivr.c:623 sofia/internal/4005@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Agent) d04f17c2-8f05-4791-acff-9272b4922032 EXECUTE sofia/internal/4005@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Agent) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:07.834007 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Agent] 2018-01-30 15:21:07.893508 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/4007@10.47.32.159 [4f4095e2-7f2d-4a4f-ad0a-1d58850df019] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] mod_sofia.c:4819 (sofia/internal/4007@10.47.32.159) State Change CS_NEW -> CS_INIT 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_session.c:615 sofia/internal/4007@10.47.32.159 set UUID=4f4095e2-7f2d-4a4f-ad0a-1d58850df019 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_INIT (Cur 3 Tot 8) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/4007@10.47.32.159) State INIT 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] mod_sofia.c:90 sofia/internal/4007@10.47.32.159 SOFIA INIT 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] sofia_glue.c:1295 sofia/internal/4007@10.47.32.159 sending invite version: 1.6.19 32bit 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 Local SDP: 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 v=0 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 o=FreeSWITCH 1517322319 1517322320 IN IP4 10.47.26.24 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 s=FreeSWITCH 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 c=IN IP4 10.47.26.24 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 t=0 0 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 m=audio 21348 RTP/AVP 102 9 0 8 3 103 104 101 13 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:102 opus/48000/2 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:9 G722/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:0 PCMU/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:8 PCMA/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:3 GSM/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:103 telephone-event/48000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=fmtp:103 0-16 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:101 telephone-event/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=fmtp:101 0-16 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:104 CN/48000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:13 CN/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=ptime:20 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=sendrecv 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37768): sent signal r_invite ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37768): recv signal r_invite 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:40 sofia/internal/4007@10.47.32.159 Standard INIT ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:280 soa_clone() soa_clone(static::041B3D50, 03C2DCB0, 03A37768) called 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/4007@10.47.32.159) State Change CS_INIT -> CS_ROUTING ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606AD40, ...) called 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/4007@10.47.32.159) State INIT going to sleep ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606AD40, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0606AD40, 00000000, 09306A0D, -1) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0606AD40, 00000000, 09306A0D, -1) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_dialog.c:338 nua_dialog_usage_add() nua(03A37768): adding session usage ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(041F1040) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0606AD40) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1426 soa_generate_offer() soa_generate_offer(static::0606AD40, 0) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606AD40, soa_generate_offer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1189 offer_answer_step() soa_static(0606AD40, soa_generate_offer): generating local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1217 offer_answer_step() soa_static(0606AD40, soa_generate_offer): upgrade with local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0552F8F0, 00000000, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1446 offer_answer_step() soa_static(0606AD40, soa_generate_offer): storing local description 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_ROUTING (Cur 3 Tot 8) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606AD40, [00000000], [0552F91C], [0552F910]) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(03D83988) tpn = */10.47.32.159:5060 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/4007@10.47.32.159) State ROUTING ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.47.32.159:5060 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] mod_sofia.c:143 sofia/internal/4007@10.47.32.159 SOFIA ROUTING ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(03D83988): not found by name */10.47.32.159:5060 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/4007@10.47.32.159) State Change CS_ROUTING -> CS_CONSUME_MEDIA 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/4007@10.47.32.159) State ROUTING going to sleep 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 8) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(03D83988): 1452 bytes of 1452 to udp/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 1452 send 1452 bytes to udp/[10.47.32.159]:5060 at 20:21:07.897008: ------------------------------------------------------------------------ INVITE sip:4007@10.47.32.159 SIP/2.0 Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bK9By01jK6evDQB Max-Forwards: 70 From: "Sergei Bobrovsky" ;tag=N8B0805D4USNe To: Call-ID: f224f3d0-809d-1236-4794-3bb0e46905d4 CSeq: 118335769 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, 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 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/4007@10.47.32.159) State CONSUME_MEDIA Content-Disposition: session Content-Length: 5394f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/4007@10.47.32.159) State CONSUME_MEDIA going to sleep X-FS-Support: update_display,send_info Remote-Party-ID: "Sergei Bobrovsky" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1517322319 1517322320 IN IP4 10.47.26.24 s=FreeSWITCH c=IN IP4 10.47.26.24 t=0 0 m=audio 21348 RTP/AVP 102 9 0 8 3 103 104 101 13 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtpmap:104 CN/48000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent INVITE (118335769) to */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(03D83988): pending 0608BEE8 for udp/10.47.26.24:5060 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37768): call state changed: init -> calling, sent offer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606AD40, [0552F930], [0552F924], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:269 nua_stack_event() nua(03A37768): event i_state INVITE sent 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.893508 [DEBUG] sofia.c:7084 Channel sofia/internal/4007@10.47.32.159 entering state [calling][0] ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608D250 from (udp/10.47.26.24:5060) has 272 bytes, veclen = 1 recv 272 bytes from udp/[10.47.32.159]:5060 at 20:21:07.900008: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bK9By01jK6evDQB To: From: "Sergei Bobrovsky" ;tag=N8B0805D4USNe Call-ID: f224f3d0-809d-1236-4794-3bb0e46905d4 CSeq: 118335769 INVITE Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608D250 (272 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (118335769) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 3.5 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608BEE8 by 03BEB778 with 0608D250 (preliminary) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608C110 from (udp/10.47.26.24:5060) has 522 bytes, veclen = 1 recv 522 bytes from udp/[10.47.32.159]:5060 at 20:21:07.984510: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.47.26.24;rport=5060;branch=z9hG4bK9By01jK6evDQB;received=10.47.26.24 To: ;tag=AIACF683B5B950670E From: "Sergei Bobrovsky" ;tag=N8B0805D4USNe Call-ID: f224f3d0-809d-1236-4794-3bb0e46905d4 CSeq: 118335769 INVITE Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,PUBLISH,UPDATE,REFER,SUBSCRIBE User-Agent: Aastra 400 P-Asserted-Identity: "Steve Larmer" Contact: Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608C110 (522 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (118335769) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608BEE8 by 03BEB778 with 0608C110 (preliminary) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37768): event r_invite 180 Ringing ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37768): call state changed: calling -> proceeding ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37768): event i_state 180 Ringing 2018-01-30 15:21:07.974010 [INFO] sofia.c:1279 sofia/internal/4007@10.47.32.159 Update Callee ID to "Steve Larmer" <4007> 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.993509 [DEBUG] sofia.c:7084 Channel sofia/internal/4007@10.47.32.159 entering state [proceeding][180] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.993509 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/4007@10.47.32.159! 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:07.993509 [DEBUG] switch_channel.c:3346 (sofia/internal/4007@10.47.32.159) Callstate Change DOWN -> RINGING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:08.054512 [DEBUG] switch_ivr.c:623 sofia/internal/4005@10.47.32.159 Command Execute export(X-Mitel-ConsulationCallingCallId=) d04f17c2-8f05-4791-acff-9272b4922032 EXECUTE sofia/internal/4005@10.47.32.159 export(X-Mitel-ConsulationCallingCallId=) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:08.054512 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-ConsulationCallingCallId]=[UNDEF] ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 10206 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608BCC0 from (udp/10.47.26.24:5060) has 497 bytes, veclen = 1 recv 497 bytes from udp/[10.47.32.159]:5060 at 20:21:10.963048: ------------------------------------------------------------------------ BYE sip:mod_sofia@10.47.26.24:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.32.159;branch=z9hG4bK_AI2018Jan302109585914510029;rport To: "IVR Team 3 5xxx" ;tag=mZj765ma7j32j From: ;tag=AI0F169B6F656BA16E Call-ID: e45daeec-809d-1236-4794-3bb0e46905d4 CSeq: 1 BYE Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,PUBLISH,UPDATE,REFER,SUBSCRIBE Allow-Events: presence,dialog,message-summary,refer Max-Forwards: 70 User-Agent: Aastra 400 Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608BCC0 (497 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2880 agent_recv_request() nta: received BYE sip:mod_sofia@10.47.26.24:5060 SIP/2.0 (CSeq 1) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3248 agent_aliases() nta: canonizing sip:mod_sofia@10.47.26.24:5060 with contact ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3060 agent_recv_request() nta: BYE (1) going to existing leg ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event i_bye 100 Trying d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [NOTICE] sofia.c:1012 Hangup sofia/internal/4005@10.47.32.159 [CS_EXECUTE] [NORMAL_CLEARING] ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37C18): sent signal r_respond ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:573 nua_stack_signal() nua(03A37C18): recv signal r_respond 200 OK ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606AC08, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37C18): sent signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(03D83988) tpn = UDP/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(03D83988): not found by name UDP/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(03D83988): 494 bytes of 494 to udp/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 494 send 494 bytes to udp/[10.47.32.159]:5060 at 20:21:10.976048: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.47.32.159;branch=z9hG4bK_AI2018Jan302109585914510029;rport=5060 From: ;tag=AI0F169B6F656BA16E To: "IVR Team 3 5xxx" ;tag=mZj765ma7j32j Call-ID: e45daeec-809d-1236-4794-3bb0e46905d4 CSeq: 1 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (1) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_dialog.c:397 nua_dialog_usage_remove_at() nua(03A37C18): removing session usage ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37C18): call state changed: ready -> terminated ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event i_state 200 Session Terminated ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37C18): event i_terminated 200 Session Terminated ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:356 soa_destroy() soa_destroy(static::0606AC08) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(06068648) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37C18): recv signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(00000000) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_session.c:2815 sofia/internal/4005@10.47.32.159 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/4005@10.47.32.159) State EXECUTE going to sleep d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4005@10.47.32.159) Running State Change CS_HANGUP (Cur 3 Tot 8) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/4005@10.47.32.159) Callstate Change ACTIVE -> HANGUP d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/4005@10.47.32.159) State HANGUP d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] mod_sofia.c:438 Channel sofia/internal/4005@10.47.32.159 hanging up, cause: NORMAL_CLEARING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:60 sofia/internal/4005@10.47.32.159 Standard HANGUP, cause: NORMAL_CLEARING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/4005@10.47.32.159) State HANGUP going to sleep d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/4005@10.47.32.159) State Change CS_HANGUP -> CS_REPORTING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4005@10.47.32.159) Running State Change CS_REPORTING (Cur 3 Tot 8) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/4005@10.47.32.159) State REPORTING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:174 sofia/internal/4005@10.47.32.159 Standard REPORTING, cause: NORMAL_CLEARING d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/4005@10.47.32.159) State REPORTING going to sleep d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/4005@10.47.32.159) State Change CS_REPORTING -> CS_DESTROY d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_session.c:1665 Session 7 (sofia/internal/4005@10.47.32.159) Locked, Waiting on external entities d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [NOTICE] switch_core_session.c:1683 Session 7 (sofia/internal/4005@10.47.32.159) Ended d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/4005@10.47.32.159 [CS_DESTROY] d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/4005@10.47.32.159) Running State Change CS_DESTROY (Cur 2 Tot 8) d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/4005@10.47.32.159) State DESTROY d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] mod_sofia.c:343 sofia/internal/4005@10.47.32.159 SOFIA DESTROY d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:181 sofia/internal/4005@10.47.32.159 Standard DESTROY d04f17c2-8f05-4791-acff-9272b4922032 2018-01-30 15:21:10.973547 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/4005@10.47.32.159) State DESTROY going to sleep 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:11.154050 [DEBUG] switch_ivr.c:623 sofia/internal/4007@10.47.32.159 Command Execute set_profile_var(caller_id_number=9145100) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 EXECUTE sofia/internal/4007@10.47.32.159 set_profile_var(caller_id_number=9145100) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608C560 from (udp/10.47.26.24:5060) has 888 bytes, veclen = 1 recv 888 bytes from udp/[10.47.32.159]:5060 at 20:21:15.042098: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.47.26.24;rport=5060;branch=z9hG4bK9By01jK6evDQB;received=10.47.26.24 To: ;tag=AIACF683B5B950670E From: "Sergei Bobrovsky" ;tag=N8B0805D4USNe Call-ID: f224f3d0-809d-1236-4794-3bb0e46905d4 CSeq: 118335769 INVITE Allow-Events: presence,dialog,message-summary,refer Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,PUBLISH,UPDATE,REFER,SUBSCRIBE User-Agent: Aastra 400 P-Asserted-Identity: "Steve Larmer" Content-Type: application/sdp Contact: Content-Length: 285 v=0 o=aastra400 442501276 442501276 IN IP4 10.47.32.159 s=call c=IN IP4 10.33.28.101 t=0 0 m=audio 3000 RTP/AVP 9 0 8 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=silenceSupp:off - - - - ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608C560 (888 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (118335769) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608BEE8 by 03BEB778 with 0608C560 ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0606AD40, 00000000, 02B9B873, 285) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1595 soa_process_answer() soa_process_answer(static::0606AD40) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606AD40, soa_process_answer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(063F3390, 093E49F0, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1304 offer_answer_step() soa_static(0606AD40, soa_process_answer): upgrade codecs with remote description ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1446 offer_answer_step() soa_static(0606AD40, soa_process_answer): storing local description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::0606AD40, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:988 nua_session_client_response() nua(03A37768): INVITE: processed SDP answer in 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37768): event r_invite 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37768): call state changed: proceeding -> completing, received answer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0606AD40, [0552F5B0], [0552F5A4], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:616 soa_get_params() soa_get_params(static::0606AD40, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37768): event i_state 200 OK 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.034100 [DEBUG] sofia.c:7084 Channel sofia/internal/4007@10.47.32.159 entering state [completing][200] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.034100 [DEBUG] sofia.c:7094 Remote SDP: 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 v=0 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 o=aastra400 442501276 442501276 IN IP4 10.47.32.159 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 s=call 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 c=IN IP4 10.33.28.101 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 t=0 0 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 m=audio 3000 RTP/AVP 9 0 8 101 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:9 G722/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:0 PCMU/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:8 PCMA/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:101 telephone-event/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=fmtp:101 0-15 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=ptime:20 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=silenceSupp:off - - - - 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37768): sent signal r_ack ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37768): recv signal r_ack ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606AD40, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::0606AD40, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(03D83988) tpn = */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(03D83988): not found by name */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(03D83988): 373 bytes of 373 to udp/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 373 send 373 bytes to udp/[10.47.32.159]:5060 at 20:21:15.052600: ------------------------------------------------------------------------ ACK sip:4007@10.47.32.159:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bKaNQS3D49B539p Max-Forwards: 70 From: "Sergei Bobrovsky" ;tag=N8B0805D4USNe To: ;tag=AIACF683B5B950670E Call-ID: f224f3d0-809d-1236-4794-3bb0e46905d4 CSeq: 118335769 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent ACK (118335769) to */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4139 signal_call_state_change() nua(03A37768): call state changed: completing -> ready ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37768): event i_state 200 ACK sent ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37768): event i_active 200 Call active 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.034100 [DEBUG] sofia.c:7084 Channel sofia/internal/4007@10.47.32.159 entering state [ready][200] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/4007@10.47.32.159 G722/8000 20 ms 160 samples 64000 bits 1 channels 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_codec.c:111 sofia/internal/4007@10.47.32.159 Original read codec set to G722:9 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:4767 sofia/internal/4007@10.47.32.159 Set 2833 dtmf send payload to 101 recv payload to 101 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/4007@10.47.32.159] 10.47.26.24 port 21348 -> 10.33.28.101 port 3000 codec: 9 ms: 20 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:7179 sofia/internal/4007@10.47.32.159 Set 2833 dtmf send payload to 101 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:7186 sofia/internal/4007@10.47.32.159 Set 2833 dtmf receive payload to 101 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_media.c:7209 sofia/internal/4007@10.47.32.159 Set rtp dtmf delay to 40 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [NOTICE] sofia.c:8218 Channel [sofia/internal/4007@10.47.32.159] has been answered 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_channel.c:3773 (sofia/internal/4007@10.47.32.159) Callstate Change RINGING -> ACTIVE 2018-01-30 15:21:15.053600 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/internal/4007@10.47.32.159] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_ivr.c:2165 (sofia/internal/4007@10.47.32.159) State Change CS_CONSUME_MEDIA -> CS_ROUTING 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_ROUTING (Cur 2 Tot 8) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/4007@10.47.32.159) State ROUTING 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] mod_sofia.c:143 sofia/internal/4007@10.47.32.159 SOFIA ROUTING 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_state_machine.c:236 sofia/internal/4007@10.47.32.159 Standard ROUTING 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [INFO] switch_channel.c:3129 sofia/internal/4007@10.47.32.159 Flipping CID from "Sergei Bobrovsky" <9145100> to "Steve Larmer" <4007> 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/4007@10.47.32.159) State Change CS_ROUTING -> CS_EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/4007@10.47.32.159) State ROUTING going to sleep 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_EXECUTE (Cur 2 Tot 8) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/4007@10.47.32.159) State EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] mod_sofia.c:198 sofia/internal/4007@10.47.32.159 SOFIA EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_core_state_machine.c:328 sofia/internal/4007@10.47.32.159 Standard EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 EXECUTE sofia/internal/4007@10.47.32.159 playback(tone_stream://%(2000,4000,440,480);loops=-1) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/4007@10.47.32.159 to inline[playback:tone_stream://${ca-ring};loops=-1,park@default] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.053600 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@16000hz 1 channels 20ms 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:15.114099 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed. ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer D fired, terminate INVITE (118335758) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/2 term, 1/4 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 11 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8982 outgoing_timer_bf() nta: timer F fired, terminating ACK (118335758) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/2 tout, 0/1 term, 1/3 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 23861 ms 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.134207 [DEBUG] switch_ivr_bridge.c:2030 (sofia/internal/9145100@10.47.32.159) State Change CS_EXECUTE -> CS_HIBERNATE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.134207 [DEBUG] switch_ivr_bridge.c:2032 (sofia/internal/4007@10.47.32.159) State Change CS_EXECUTE -> CS_HIBERNATE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_play_say.c:1942 done playing file tone_stream://%(2000,4000,440,480);loops=-1 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_play_say.c:1942 done playing file local_stream://74cefb6e-becb-4316-8c75-3042dfdd1f18 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/4007@10.47.32.159) State EXECUTE going to sleep 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_HIBERNATE (Cur 2 Tot 8) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/4007@10.47.32.159) State HIBERNATE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] mod_sofia.c:180 sofia/internal/4007@10.47.32.159 SOFIA HIBERNATE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_bridge.c:984 (sofia/internal/4007@10.47.32.159) State Change CS_HIBERNATE -> CS_RESET 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/4007@10.47.32.159) State HIBERNATE going to sleep 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_RESET (Cur 2 Tot 8) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/4007@10.47.32.159) State RESET 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] mod_sofia.c:161 sofia/internal/4007@10.47.32.159 SOFIA RESET 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_bridge.c:969 sofia/internal/4007@10.47.32.159 CUSTOM RESET 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:188 sofia/internal/4007@10.47.32.159 Standard RESET 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/4007@10.47.32.159) State RESET going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/9145100@10.47.32.159) State EXECUTE going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_HIBERNATE (Cur 2 Tot 8) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/9145100@10.47.32.159) State HIBERNATE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] mod_sofia.c:180 sofia/internal/9145100@10.47.32.159 SOFIA HIBERNATE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_bridge.c:984 (sofia/internal/9145100@10.47.32.159) State Change CS_HIBERNATE -> CS_RESET 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/9145100@10.47.32.159) State HIBERNATE going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_RESET (Cur 2 Tot 8) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/9145100@10.47.32.159) State RESET 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] mod_sofia.c:161 sofia/internal/9145100@10.47.32.159 SOFIA RESET 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_bridge.c:969 sofia/internal/9145100@10.47.32.159 CUSTOM RESET 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_bridge.c:976 (sofia/internal/9145100@10.47.32.159) State Change CS_RESET -> CS_SOFT_EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/9145100@10.47.32.159) State RESET going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/9145100@10.47.32.159) Running State Change CS_SOFT_EXECUTE (Cur 2 Tot 8) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/9145100@10.47.32.159) State SOFT_EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_bridge.c:994 sofia/internal/9145100@10.47.32.159 CUSTOM SOFT_EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_bridge.c:1026 (sofia/internal/4007@10.47.32.159) State Change CS_RESET -> CS_SOFT_EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_SOFT_EXECUTE (Cur 2 Tot 8) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/4007@10.47.32.159) State SOFT_EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_ivr_bridge.c:994 sofia/internal/4007@10.47.32.159 CUSTOM SOFT_EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:400 sofia/internal/4007@10.47.32.159 Standard SOFT_EXECUTE 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.153707 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/4007@10.47.32.159) State SOFT_EXECUTE going to sleep 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] switch_ivr_bridge.c:1509 (sofia/internal/4007@10.47.32.159) State Change CS_SOFT_EXECUTE -> CS_CONSUME_MEDIA 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 8) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/4007@10.47.32.159) State CONSUME_MEDIA 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] switch_ivr_bridge.c:933 sofia/internal/4007@10.47.32.159 CUSTOM HOLD 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/4007@10.47.32.159) State CONSUME_MEDIA going to sleep 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.174707 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute set_profile_var(caller_id_number=4007) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 set_profile_var(caller_id_number=4007) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] switch_ivr_bridge.c:1614 (sofia/internal/4007@10.47.32.159) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4007@10.47.32.159) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 8) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/4007@10.47.32.159) State EXCHANGE_MEDIA 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37768): sent signal r_update ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37768): recv signal r_update ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606AD40, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0606AD40) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1426 soa_generate_offer() soa_generate_offer(static::0606AD40, 0) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606AD40, soa_generate_offer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(063F43F8, 00000000, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606AD40, [00000000], [0552F948], [0552F93C]) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(03D83988) tpn = */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(03D83988): not found by name */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(03D83988): 1238 bytes of 1238 to udp/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37510): sent signal r_update ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 1238 send 1238 bytes to udp/[10.47.32.159]:5060 at 20:21:22.187207: ------------------------------------------------------------------------ UPDATE sip:4007@10.47.32.159:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bKBygj58mD9Dtvj Max-Forwards: 70 From: "Sergei Bobrovsky" ;tag=N8B0805D4USNe To: ;tag=AIACF683B5B950670E Call-ID: f224f3d0-809d-1236-4794-3bb0e46905d4 CSeq: 118335770 UPDATE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 539 P-Asserted-Identity: "IVR Team 3 5xxx" v=0 o=FreeSWITCH 1517322319 1517322320 IN IP4 10.47.26.24 s=FreeSWITCH c=IN IP4 10.47.26.24 t=0 0 m=audio 21348 RTP/AVP 9 0 8 101 102 3 103 104 13 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:3 GSM/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtpmap:104 CN/48000 a=rtpmap:13 CN/8000 a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent UPDATE (118335770) to */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(03D83988): pending 0608C110 for udp/10.47.26.24:5060 (already 0) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1348 set_timeout() nta: timer shortened to 1000 ms ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4145 signal_call_state_change() nua(03A37768): ready call updated: calling sent offer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606AD40, [0552F95C], [0552F950], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:269 nua_stack_event() nua(03A37768): event i_state UPDATE sent ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37510): recv signal r_update ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606A998, ...) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0606A998) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1426 soa_generate_offer() soa_generate_offer(static::0606A998, 0) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606A998, soa_generate_offer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0646AFE8, 00000000, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606A998, [00000000], [0552F948], [0552F93C]) called ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(03D83988) tpn = */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4680 tport_by_addrinfo() tport(03D83988): not found by name */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(03D83988): 932 bytes of 932 to udp/10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 932 send 932 bytes to udp/[10.47.32.159]:5060 at 20:21:22.188207: ------------------------------------------------------------------------ UPDATE sip:9145100@10.47.32.159:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.26.24;rport;branch=z9hG4bKc79a735g6pgFe Max-Forwards: 70 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.174707 [DEBUG] sofia.c:7084 Channel sofia/internal/4007@10.47.32.159 entering state [calling][0] From: ;tag=KpSe5a4699cgQ To: "IVR Team 3 5xxx" ;tag=AI2213AE6C7868B46B Call-ID: AI79A7BDE8B4252507_00:08:5d:8d:5e:e0 CSeq: 118335760 UPDATE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 218 P-Asserted-Identity: "Sergei Bobrovsky" v=0 o=FreeSWITCH 1517321370 1517321371 IN IP4 10.47.26.24 s=FreeSWITCH c=IN IP4 10.47.26.24 t=0 0 m=audio 22272 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8304 outgoing_send() nta: sent UPDATE (118335760) to */10.47.32.159:5060 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4160 tport_pend() tport_pend(03D83988): pending 0608E5B8 for udp/10.47.26.24:5060 (already 1) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4145 signal_call_state_change() nua(03A37510): ready call updated: calling sent offer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0606A998, [0552F95C], [0552F950], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:269 nua_stack_event() nua(03A37510): event i_state UPDATE sent 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.194707 [DEBUG] sofia.c:7084 Channel sofia/internal/9145100@10.47.32.159 entering state [calling][0] ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608EA08 from (udp/10.47.26.24:5060) has 888 bytes, veclen = 1 recv 888 bytes from udp/[10.47.32.159]:5060 at 20:21:22.196707: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.47.26.24;rport=5060;branch=z9hG4bKBygj58mD9Dtvj;received=10.47.26.24 To: ;tag=AIACF683B5B950670E From: "Sergei Bobrovsky" ;tag=N8B0805D4USNe Call-ID: f224f3d0-809d-1236-4794-3bb0e46905d4 CSeq: 118335770 UPDATE Contact: Allow-Events: presence,dialog,message-summary,refer Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,PUBLISH,UPDATE,REFER,SUBSCRIBE User-Agent: Aastra 400 P-Asserted-Identity: "Steve Larmer" Content-Type: application/sdp Content-Length: 285 v=0 o=aastra400 442501276 442501277 IN IP4 10.47.32.159 s=call c=IN IP4 10.33.28.101 t=0 0 m=audio 3000 RTP/AVP 9 0 8 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=silenceSupp:off - - - - ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608EA08 (888 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for UPDATE (118335770) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 10.501 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608C110 by 03BEB860 with 0608EA08 ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0606AD40, 00000000, 094C1D73, 285) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1595 soa_process_answer() soa_process_answer(static::0606AD40) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606AD40, soa_process_answer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(063F43F8, 0645D570, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1304 offer_answer_step() soa_static(0606AD40, soa_process_answer): upgrade codecs with remote description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::0606AD40, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:988 nua_session_client_response() nua(03A37768): UPDATE: processed SDP answer in 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37768): event r_update 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4145 signal_call_state_change() nua(03A37768): ready call updated: ready received answer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0606AD40, [0552F5EC], [0552F5E0], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:616 soa_get_params() soa_get_params(static::0606AD40, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37768): event i_state 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37768): event i_active 200 Call active ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(03D83988): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(03D83988) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(03D83988) msg 0608E390 from (udp/10.47.26.24:5060) has 938 bytes, veclen = 1 recv 938 bytes from udp/[10.47.32.159]:5060 at 20:21:22.204208: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.47.26.24;rport=5060;branch=z9hG4bKc79a735g6pgFe;received=10.47.26.24 To: "IVR Team 3 5xxx" ;tag=AI2213AE6C7868B46B From: ;tag=KpSe5a4699cgQ Call-ID: AI79A7BDE8B4252507_00:08:5d:8d:5e:e0 CSeq: 118335760 UPDATE Contact: Allow-Events: presence,dialog,message-summary,refer Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,PUBLISH,UPDATE,REFER,SUBSCRIBE User-Agent: Aastra 400 P-Asserted-Identity: "IVR Team 3 5xxx" Content-Type: application/sdp Content-Length: 324 v=0 o=aastra400 1929707267 1929707269 IN IP4 10.47.32.159 s=call c=IN IP4 10.47.26.150 t=0 0 m=audio 50376 RTP/AVP 102 0 8 18 121 101 a=rtpmap:102 G7221/16000 a=fmtp:102 bitrate=32000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:121 L16/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(03D83988): msg 0608E390 (938 bytes) from udp/10.47.32.159:5060/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3299 agent_recv_response() nta: received 200 OK for UPDATE (118335760) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 16.501 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:4222 tport_release() tport(03D83988): 0608E5B8 by 03BEBB18 with 0608E390 ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0606A998, 00000000, 0946BF8E, 324) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1595 soa_process_answer() soa_process_answer(static::0606A998) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0606A998, soa_process_answer): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0646AFE8, 041F7E20, ""): called ..\..\sofia-sip\libsofia-sip-ua\soa\soa_static.c:1304 offer_answer_step() soa_static(0606A998, soa_process_answer): upgrade codecs with remote description ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1730 soa_activate() soa_activate(static::0606A998, (nil)) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:988 nua_session_client_response() nua(03A37510): UPDATE: processed SDP answer in 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event r_update 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_session.c:4145 signal_call_state_change() nua(03A37510): ready call updated: ready received answer ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0606A998, [0552F5EC], [0552F5E0], [00000000]) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:616 soa_get_params() soa_get_params(static::0606A998, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event i_state 200 OK ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37510): event i_active 200 Call active 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [NOTICE] switch_core_io.c:1202 Activating write resampler 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] sofia.c:7084 Channel sofia/internal/9145100@10.47.32.159 entering state [ready][200] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] sofia.c:7094 Remote SDP: 02d73189-6308-41ce-ac11-3e9e829c91c3 v=0 02d73189-6308-41ce-ac11-3e9e829c91c3 o=aastra400 1929707267 1929707269 IN IP4 10.47.32.159 02d73189-6308-41ce-ac11-3e9e829c91c3 s=call 02d73189-6308-41ce-ac11-3e9e829c91c3 c=IN IP4 10.47.26.150 02d73189-6308-41ce-ac11-3e9e829c91c3 t=0 0 02d73189-6308-41ce-ac11-3e9e829c91c3 m=audio 50376 RTP/AVP 102 0 8 18 121 101 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:102 G7221/16000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:102 bitrate=32000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:18 G729/8000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:18 annexb=no 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:121 L16/16000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=rtpmap:101 telephone-event/8000 02d73189-6308-41ce-ac11-3e9e829c91c3 a=fmtp:101 0-15 02d73189-6308-41ce-ac11-3e9e829c91c3 a=ptime:20 02d73189-6308-41ce-ac11-3e9e829c91c3 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:0:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[opus:116:48000:20:0:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[G722:9:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [L16:121:16000:20:0:1]/[GSM:3:8000:20:13200:1] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4767 sofia/internal/9145100@10.47.32.159 Set 2833 dtmf send payload to 101 recv payload to 101 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] sofia.c:8061 Processing updated SDP 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/9145100@10.47.32.159. 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.214708 [NOTICE] switch_core_io.c:1202 Activating write resampler 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] sofia.c:7084 Channel sofia/internal/4007@10.47.32.159 entering state [ready][200] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] sofia.c:7094 Remote SDP: 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 v=0 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 o=aastra400 442501276 442501277 IN IP4 10.47.32.159 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 s=call 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 c=IN IP4 10.33.28.101 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 t=0 0 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 m=audio 3000 RTP/AVP 9 0 8 101 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:9 G722/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:0 PCMU/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:8 PCMA/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=rtpmap:101 telephone-event/8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=fmtp:101 0-15 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=ptime:20 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 a=silenceSupp:off - - - - 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:4767 sofia/internal/4007@10.47.32.159 Set 2833 dtmf send payload to 101 recv payload to 101 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] sofia.c:8061 Processing updated SDP 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.214708 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/4007@10.47.32.159. 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.374209 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-ISINITIALDIRECTIONOUTBOUND=false) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-ISINITIALDIRECTIONOUTBOUND=false) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.374209 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-ISINITIALDIRECTIONOUTBOUND]=[false] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.414210 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CallState=UNHELD) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CallState=UNHELD) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.414210 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CallState]=[UNHELD] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.454710 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Agent) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:22.454710 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Agent] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.494210 [DEBUG] switch_ivr.c:623 sofia/internal/4007@10.47.32.159 Command Execute export(X-Mitel-CallState=UNHELD) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 EXECUTE sofia/internal/4007@10.47.32.159 export(X-Mitel-CallState=UNHELD) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.494210 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CallState]=[UNHELD] 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.994218 [DEBUG] switch_ivr.c:623 sofia/internal/4007@10.47.32.159 Command Execute export(X-Mitel-CALLEDDEVICETYPE=Agent) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 EXECUTE sofia/internal/4007@10.47.32.159 export(X-Mitel-CALLEDDEVICETYPE=Agent) 4f4095e2-7f2d-4a4f-ad0a-1d58850df019 2018-01-30 15:21:22.994218 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CALLEDDEVICETYPE]=[Agent] ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 4009 ms 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:23.513724 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-ConsulationTransfer=false) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-ConsulationTransfer=false) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:23.513724 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-ConsulationTransfer]=[false] 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:23.573725 [DEBUG] switch_ivr.c:623 sofia/internal/9145100@10.47.32.159 Command Execute export(X-Mitel-CallState=ACTIVE) 02d73189-6308-41ce-ac11-3e9e829c91c3 EXECUTE sofia/internal/9145100@10.47.32.159 export(X-Mitel-CallState=ACTIVE) 02d73189-6308-41ce-ac11-3e9e829c91c3 2018-01-30 15:21:23.573725 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [X-Mitel-CallState]=[ACTIVE] ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate UPDATE (118335770) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/3 term, 1/4 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 8 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate UPDATE (118335760) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 15772 ms ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2773 tport_wakeup() tport_wakeup(060938C8): events HUP ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2826 tport_hup_event() tport(060938C8) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2157 tport_shutdown0() tport(060938C8, 2) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2090 tport_close() tport(060938C8): tcp/10.47.26.79:53806/sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2263 tport_set_secondary_timer() tport(060938C8): set timer at 0 ms because zap ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(041B9598): events ACCEPT ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:862 tport_alloc_secondary() tport(041B9598): new secondary tport 060931C0 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2640 tport_accept() tport(060931C0): new connection from tcp/10.47.26.79:53867/sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2773 tport_wakeup() tport_wakeup(060931C0): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(060931C0) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(060931C0) msg 0608B420 from (tcp/10.47.26.79:53867) has 502 bytes, veclen = 1 recv 502 bytes from tcp/[10.47.26.79]:53867 at 20:21:29.886806: ------------------------------------------------------------------------ OPTIONS sip:jghantous-pc.Lync2013IVR.local SIP/2.0 FROM: ;epid=A6F13CCF53;tag=eb6fbb7b28 TO: CSEQ: 1790346 OPTIONS CALL-ID: 47395c01209b4d39880c4a0d7d7fbd5e MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 10.47.26.79:53867;branch=z9hG4bK7c3533a CONTACT: CONTENT-LENGTH: 0 USER-AGENT: RTCC/6.0.0.0 MediationServer ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(060931C0): msg 0608B420 (502 bytes) from tcp/10.47.26.79:53867/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2880 agent_recv_request() nta: received OPTIONS sip:jghantous-pc.Lync2013IVR.local SIP/2.0 (CSeq 1790346) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3085 agent_recv_request() nta: OPTIONS (1790346) going to a default leg ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:280 soa_clone() soa_clone(static::041B3D50, 03C2DCB0, 03A37E70) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606A110, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37E70): event i_options 100 Trying ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2296 tport_set_secondary_timer() tport(060931C0): reset timer ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37E70): sent signal r_respond ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:573 nua_stack_signal() nua(03A37E70): recv signal r_respond 200 OK ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606A110, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37E70): sent signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0606A110, [00000000], [0552F9CC], [0552F9C0]) called ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(060931C0) tpn = TCP/10.47.26.79:53867 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(060931C0): 768 bytes of 768 to tcp/10.47.26.79:53867 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 768 send 768 bytes to tcp/[10.47.26.79]:53867 at 20:21:29.887306: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.47.26.79:53867;branch=z9hG4bK7c3533a;rport=53867 FROM: ;epid=A6F13CCF53;tag=eb6fbb7b28 To: ;tag=pH5ravpH14F8S CALL-ID: 47395c01209b4d39880c4a0d7d7fbd5e CSEQ: 1790346 OPTIONS Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, 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 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2296 tport_set_secondary_timer() tport(060931C0): reset timer ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:6791 incoming_reply() nta: sent 200 OK for OPTIONS (1790346) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2296 tport_set_secondary_timer() tport(060931C0): reset timer ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:5744 incoming_free() nta: incoming_free(063E5998) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37E70): recv signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(00000000) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:356 soa_destroy() soa_destroy(static::0606A110) called ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2773 tport_wakeup() tport_wakeup(06092C20): events HUP ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2826 tport_hup_event() tport(06092C20) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2157 tport_shutdown0() tport(06092C20, 2) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2090 tport_close() tport(06092C20): tcp/10.47.26.78:59091/sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2263 tport_set_secondary_timer() tport(06092C20): set timer at 0 ms because zap ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(041B9598): events ACCEPT ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:862 tport_alloc_secondary() tport(041B9598): new secondary tport 060935F8 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2640 tport_accept() tport(060935F8): new connection from tcp/10.47.26.78:59257/sip ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2773 tport_wakeup() tport_wakeup(060935F8): events IN ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2864 tport_recv_event() tport_recv_event(060935F8) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3205 tport_recv_iovec() tport(060935F8) msg 0608E390 from (tcp/10.47.26.78:59257) has 503 bytes, veclen = 1 recv 503 bytes from tcp/[10.47.26.78]:59257 at 20:21:31.959924: ------------------------------------------------------------------------ OPTIONS sip:jghantous-pc.Lync2013IVR.local SIP/2.0 FROM: ;epid=910A1B93A0;tag=b09d7b85db TO: CSEQ: 1713761 OPTIONS CALL-ID: 6b638669592d4e9c951eb39410f6a84c MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 10.47.26.78:59257;branch=z9hG4bK53d7acbc CONTACT: CONTENT-LENGTH: 0 USER-AGENT: RTCC/6.0.0.0 MediationServer ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3023 tport_deliver() tport(060935F8): msg 0608E390 (503 bytes) from tcp/10.47.26.78:59257/sip next=00000000 ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:2880 agent_recv_request() nta: received OPTIONS sip:jghantous-pc.Lync2013IVR.local SIP/2.0 (CSeq 1713761) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:3085 agent_recv_request() nta: OPTIONS (1713761) going to a default leg ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:280 soa_clone() soa_clone(static::041B3D50, 03C2DCB0, 03A37F38) called ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606BE50, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:271 nua_stack_event() nua(03A37F38): event i_options 100 Trying ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2296 tport_set_secondary_timer() tport(060935F8): reset timer ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37F38): sent signal r_respond ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:573 nua_stack_signal() nua(03A37F38): recv signal r_respond 200 OK ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:403 soa_set_params() soa_set_params(static::0606BE50, ...) called ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:529 nua_signal() nua(03A37F38): sent signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0606BE50, [00000000], [0552F9CC], [0552F9C0]) called ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3257 tport_tsend() tport_tsend(060935F8) tpn = TCP/10.47.26.78:59257 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3594 tport_vsend() tport_vsend(060935F8): 769 bytes of 769 to tcp/10.47.26.78:59257 ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:3492 tport_send_msg() tport_vsend returned 769 send 769 bytes to tcp/[10.47.26.78]:59257 at 20:21:31.960423: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 10.47.26.78:59257;branch=z9hG4bK53d7acbc;rport=59257 FROM: ;epid=910A1B93A0;tag=b09d7b85db To: ;tag=QtyHcQ7myD6tN CALL-ID: 6b638669592d4e9c951eb39410f6a84c CSEQ: 1713761 OPTIONS Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19~32bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, 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 ------------------------------------------------------------------------ ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2296 tport_set_secondary_timer() tport(060935F8): reset timer ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:6791 incoming_reply() nta: sent 200 OK for OPTIONS (1713761) ..\..\sofia-sip\libsofia-sip-ua\tport\tport.c:2296 tport_set_secondary_timer() tport(060935F8): reset timer ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:5744 incoming_free() nta: incoming_free(063E5588) ..\..\sofia-sip\libsofia-sip-ua\nua\nua_stack.c:569 nua_stack_signal() nua(03A37F38): recv signal r_destroy ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:4470 nta_leg_destroy() nta_leg_destroy(00000000) ..\..\sofia-sip\libsofia-sip-ua\soa\soa.c:356 soa_destroy() soa_destroy(static::0606BE50) called 2018-01-30 15:21:39.154015 [DEBUG] switch_core_file.c:342 File C:\program files (x86)\Mitel\MiContact Center\Ivr\Media\Songs\74cefb6e-becb-4316-8c75-3042dfdd1f18/bensound-goinghigher.wav sample rate 44100 doesn't match requested rate 8000 2018-01-30 15:21:39.154015 [WARNING] switch_core_file.c:360 File has 2 channels, muxing to 1 channel will occur. ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all(00000000, 00000000, 0552FAD4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 4065 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:9101 outgoing_timer_dk() nta: timer D fired, terminate INVITE (118335769) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/1 term, 1/2 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1296 agent_timer() nta: timer set next to 10 ms ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8982 outgoing_timer_bf() nta: timer F fired, terminating ACK (118335769) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all(00000000, 00000000, 0552FAF4) ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 1/1 free ..\..\sofia-sip\libsofia-sip-ua\nta\nta.c:1289 agent_timer() nta: timer not set