recv 1529 bytes from udp/[139.59.19.72]:5060 at 19:48:44.618377: ------------------------------------------------------------------------ INVITE sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test SIP/2.0 Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKS3Q3S5merHy4p Max-Forwards: 69 From: "Extension 1000" ;tag=71jX784Kjc7Hr To: Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518797 INVITE Contact: User-Agent: Shashi-switch-sip 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 Session-Expires: 120;refresher=uac Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 491 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1000" ;party=calling;screen=yes;privacy=off v=0 o=Shashi-switch-sdp 1527689106 1527689107 IN IP4 139.59.19.72 s=Shashi-switch-sdp c=IN IP4 139.59.19.72 t=0 0 m=audio 20616 RTP/AVP 102 9 0 8 103 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2018-05-30 19:48:44.613113 [NOTICE] switch_channel.c:1104 New Channel sofia/external/1000@139.59.19.72 [7908aba4-48e6-40ac-832f-f7ca7ce7be11] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_NEW (Cur 1 Tot 12) 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:10078 sofia/external/1000@139.59.19.72 receiving invite from 139.59.19.72:5060 version: 1.9.0 git ed4920e 2018-05-04 14:37:06Z 64bit 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [received][100] 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=Shashi-switch-sdp 1527689106 1527689107 IN IP4 139.59.19.72 s=Shashi-switch-sdp c=IN IP4 139.59.19.72 t=0 0 m=audio 20616 RTP/AVP 102 9 0 8 103 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:7693 (sofia/external/1000@139.59.19.72) State Change CS_NEW -> CS_INIT 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:603 (sofia/external/1000@139.59.19.72) State NEW 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_INIT (Cur 1 Tot 12) 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1000@139.59.19.72) State INIT 2018-05-30 19:48:44.613113 [DEBUG] mod_sofia.c:93 sofia/external/1000@139.59.19.72 SOFIA INIT 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:40 sofia/external/1000@139.59.19.72 Standard INIT 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:48 (sofia/external/1000@139.59.19.72) State Change CS_INIT -> CS_ROUTING 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1000@139.59.19.72) State INIT going to sleep 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_ROUTING (Cur 1 Tot 12) 2018-05-30 19:48:44.613113 [DEBUG] switch_channel.c:2249 (sofia/external/1000@139.59.19.72) Callstate Change DOWN -> RINGING 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1000@139.59.19.72) State ROUTING send 401 bytes to udp/[139.59.19.72]:5060 at 19:48:44.619491: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKS3Q3S5merHy4p From: "Extension 1000" ;tag=71jX784Kjc7Hr To: Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518797 INVITE User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:48:44.613113 [DEBUG] mod_sofia.c:154 sofia/external/1000@139.59.19.72 SOFIA ROUTING 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:236 sofia/external/1000@139.59.19.72 Standard ROUTING 2018-05-30 19:48:44.613113 [INFO] mod_dialplan_xml.c:637 Processing Extension 1000 <1000>->1001 in context public Dialplan: sofia/external/1000@139.59.19.72 parsing [public->record_rest] continue=false Dialplan: sofia/external/1000@139.59.19.72 Regex (PASS) [record_rest] ${destination_number}(1001) =~ /1001/ break=on-false Dialplan: sofia/external/1000@139.59.19.72 Action answer() Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_TITLE=Recording ${destination_number} ${caller_id_number} ${strftime(%Y-%m-%d %H:%M)}) Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_COPYRIGHT=(c) 1980 Factory Records, Inc.) Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_SOFTWARE=FreeSWITCH) Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_ARTIST=Ian Curtis) Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_COMMENT=Love will tear us apart) Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_DATE=${strftime(%Y-%m-%d %H:%M)}) Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_STEREO=true) Dialplan: sofia/external/1000@139.59.19.72 Action record_session(/usr/local/freeswitch/recordings/${strftime(%Y-%m-%d-%H-%M-%S)}_${destination_number}_${caller_id_number}.wav) Dialplan: sofia/external/1000@139.59.19.72 Action set(ringback=${us-ring}) Dialplan: sofia/external/1000@139.59.19.72 Action bridge(user/1003) 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:286 (sofia/external/1000@139.59.19.72) State Change CS_ROUTING -> CS_EXECUTE 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1000@139.59.19.72) State ROUTING going to sleep 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_EXECUTE (Cur 1 Tot 12) 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1000@139.59.19.72) State EXECUTE 2018-05-30 19:48:44.613113 [DEBUG] mod_sofia.c:209 sofia/external/1000@139.59.19.72 SOFIA EXECUTE 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:328 sofia/external/1000@139.59.19.72 Standard EXECUTE EXECUTE sofia/external/1000@139.59.19.72 answer() 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[opus:116:48000:20:0:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[G722:9:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMU:0:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMA:8:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5047 Set telephone-event payload to 103@48000 2018-05-30 19:48:44.613113 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:44.613113 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:3446 Set Codec sofia/external/1000@139.59.19.72 opus/48000 20 ms 960 samples 0 bits 2 channels 2018-05-30 19:48:44.613113 [DEBUG] switch_core_codec.c:111 sofia/external/1000@139.59.19.72 Original read codec set to opus:116 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5390 Set telephone-event payload to 103@48000 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5448 sofia/external/1000@139.59.19.72 Set 2833 dtmf send payload to 103 recv payload to 103 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8164 AUDIO RTP [sofia/external/1000@139.59.19.72] 159.89.163.195 port 28298 -> 139.59.19.72 port 20616 codec: 102 ms: 20 2018-05-30 19:48:44.613113 [DEBUG] switch_rtp.c:4189 Starting timer [soft] 960 bytes per 20ms 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8468 sofia/external/1000@139.59.19.72 Set 2833 dtmf send payload to 103 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8475 sofia/external/1000@139.59.19.72 Set 2833 dtmf receive payload to 103 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8498 sofia/external/1000@139.59.19.72 Set rtp dtmf delay to 40 2018-05-30 19:48:44.613113 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/1000@139.59.19.72! 2018-05-30 19:48:44.613113 [DEBUG] switch_channel.c:3482 (sofia/external/1000@139.59.19.72) Callstate Change RINGING -> EARLY 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8147 Audio params are unchanged for sofia/external/1000@139.59.19.72. 2018-05-30 19:48:44.613113 [DEBUG] mod_sofia.c:881 Local SDP sofia/external/1000@139.59.19.72: v=0 o=FreeSWITCH 1527681426 1527681427 IN IP4 159.89.163.195 s=FreeSWITCH c=IN IP4 159.89.163.195 t=0 0 m=audio 28298 RTP/AVP 102 103 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=ptime:20 a=sendrecv send 1292 bytes to udp/[139.59.19.72]:5060 at 19:48:44.622729: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKS3Q3S5merHy4p From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518797 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Session-Expires: 120;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 305 X-FS-Display-Name: 1001 X-FS-Display-Number: sip:1001@159.89.163.195 X-FS-Support: update_display,send_info Remote-Party-ID: "1001" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1527681426 1527681427 IN IP4 159.89.163.195 s=FreeSWITCH c=IN IP4 159.89.163.195 t=0 0 m=audio 28298 RTP/AVP 102 103 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=ptime:20 ------------------------------------------------------------------------ 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [completed][200] 2018-05-30 19:48:44.613113 [NOTICE] mod_dptools.c:1357 Channel [sofia/external/1000@139.59.19.72] has been answered 2018-05-30 19:48:44.623061 [DEBUG] switch_channel.c:3781 (sofia/external/1000@139.59.19.72) Callstate Change EARLY -> ACTIVE EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_TITLE=Recording 1001 1000 2018-05-30 19:48) 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_TITLE]=[Recording 1001 1000 2018-05-30 19:48] EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_COPYRIGHT=(c) 1980 Factory Records, Inc.) 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_COPYRIGHT]=[(c) 1980 Factory Records, Inc.] EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_SOFTWARE=FreeSWITCH) 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_SOFTWARE]=[FreeSWITCH] EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_ARTIST=Ian Curtis) 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_ARTIST]=[Ian Curtis] EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_COMMENT=Love will tear us apart) 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_COMMENT]=[Love will tear us apart] EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_DATE=2018-05-30 19:48) 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_DATE]=[2018-05-30 19:48] EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_STEREO=true) 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_STEREO]=[true] EXECUTE sofia/external/1000@139.59.19.72 record_session(/usr/local/freeswitch/recordings/2018-05-30-19-48-44_1001_1000.wav) recv 441 bytes from udp/[139.59.19.72]:5060 at 19:48:44.625458: ------------------------------------------------------------------------ ACK sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0 Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKtcHvU05HNtmQj Max-Forwards: 70 From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518797 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:48:44.633064 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/external/1000@139.59.19.72 2018-05-30 19:48:44.633064 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [ready][200] EXECUTE sofia/external/1000@139.59.19.72 set(ringback=%(2000,4000,440,480)) 2018-05-30 19:48:44.633064 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/external/1000@139.59.19.72 bridge(user/1003) 2018-05-30 19:48:44.633064 [DEBUG] switch_channel.c:1823 (sofia/external/1000@139.59.19.72) Callstate Change ACTIVE -> RING_WAIT 2018-05-30 19:48:44.633064 [DEBUG] switch_ivr_originate.c:2159 Parsing global variables 2018-05-30 19:48:44.633064 [DEBUG] switch_ivr_originate.c:2159 Parsing global variables 2018-05-30 19:48:44.633064 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1003@124.123.68.233:10222 [e66214b9-c6df-4e56-a9d9-15aa00d65775] 2018-05-30 19:48:44.633064 [DEBUG] mod_sofia.c:5026 (sofia/internal/1003@124.123.68.233:10222) State Change CS_NEW -> CS_INIT 2018-05-30 19:48:44.633064 [NOTICE] switch_ivr_originate.c:2868 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_INIT (Cur 2 Tot 13) 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1003@124.123.68.233:10222) State INIT 2018-05-30 19:48:44.633064 [DEBUG] mod_sofia.c:93 sofia/internal/1003@124.123.68.233:10222 SOFIA INIT 2018-05-30 19:48:44.633064 [DEBUG] sofia_glue.c:1299 sofia/internal/1003@124.123.68.233:10222 sending invite version: 1.9.0 git ed4920e 2018-05-04 14:37:06Z 64bit Local SDP: v=0 o=FreeSWITCH 1527688610 1527688611 IN IP4 159.89.163.195 s=FreeSWITCH c=IN IP4 159.89.163.195 t=0 0 m=audio 21114 RTP/AVP 102 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:101 telephone-event/48000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv send 1406 bytes to tcp/[124.123.68.233]:10222 at 19:48:44.641242: ------------------------------------------------------------------------ INVITE sip:1003@124.123.68.233:10222;transport=TCP;rinstance=621965d30a4d4f92 SIP/2.0 Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKr6g3ZcgBeFr8Q Max-Forwards: 68 From: "Extension 1000" ;tag=03e14v3jr65Ua To: Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88 CSeq: 123518798 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit 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: 343 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1000" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1527688610 1527688611 IN IP4 159.89.163.195 s=FreeSWITCH c=IN IP4 159.89.163.195 t=0 0 m=audio 21114 RTP/AVP 102 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:101 telephone-event/48000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1003@124.123.68.233:10222 Standard INIT 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1003@124.123.68.233:10222) State Change CS_INIT -> CS_ROUTING 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1003@124.123.68.233:10222) State INIT going to sleep 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_ROUTING (Cur 2 Tot 13) 2018-05-30 19:48:44.633064 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@124.123.68.233:10222 entering state [calling][0] 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1003@124.123.68.233:10222) State ROUTING 2018-05-30 19:48:44.633064 [DEBUG] mod_sofia.c:154 sofia/internal/1003@124.123.68.233:10222 SOFIA ROUTING 2018-05-30 19:48:44.633064 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1003@124.123.68.233:10222) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1003@124.123.68.233:10222) State ROUTING going to sleep 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 13) 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1003@124.123.68.233:10222) State CONSUME_MEDIA 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1003@124.123.68.233:10222) State CONSUME_MEDIA going to sleep 2018-05-30 19:48:44.633064 [DEBUG] switch_ivr_async.c:1508 No silence detection configured; assuming start of speech freeswitch@debian-s-1vcpu-1gb-blr1-01> freeswitch@debian-s-1vcpu-1gb-blr1-01> recv 324 bytes from tcp/[124.123.68.233]:10222 at 19:48:44.742629: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKr6g3ZcgBeFr8Q To: From: "Extension 1000" ;tag=03e14v3jr65Ua Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88 CSeq: 123518798 INVITE Content-Length: 0 ------------------------------------------------------------------------ freeswitch@debian-s-1vcpu-1gb-blr1-01> freeswitch@debian-s-1vcpu-1gb-blr1-01> freeswitch@debian-s-1vcpu-1gb-blr1-01> freeswitch@debian-s-1vcpu-1gb-blr1-01> freeswitch@debian-s-1vcpu-1gb-blr1-01> recv 718 bytes from udp/[139.59.19.72]:5060 at 19:48:44.946359: ------------------------------------------------------------------------ INFO sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0 Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKUNaNXUpNj3aae Max-Forwards: 70 From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518798 INFO Contact: User-Agent: Shashi-switch-sip Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 1000 ------------------------------------------------------------------------ send 537 bytes to udp/[139.59.19.72]:5060 at 19:48:44.961574: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKUNaNXUpNj3aae From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518798 INFO User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:48:45.113092 [DEBUG] switch_rtp.c:7373 Correct audio ip/port confirmed. 2018-05-30 19:48:45.113092 [DEBUG] switch_core_io.c:448 Setting BUG Codec opus:116 2018-05-30 19:48:45.113092 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] recv 544 bytes from tcp/[124.123.68.233]:10222 at 19:48:45.747861: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKr6g3ZcgBeFr8Q Contact: To: ;tag=b0260860 From: "Extension 1000" ;tag=03e14v3jr65Ua Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88 CSeq: 123518798 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE User-Agent: Z 5.2.14 rv2.8.88 Allow-Events: presence, kpml, talk Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:48:45.743076 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@124.123.68.233:10222 entering state [proceeding][180] 2018-05-30 19:48:45.743076 [NOTICE] sofia.c:7399 Ring-Ready sofia/internal/1003@124.123.68.233:10222! 2018-05-30 19:48:45.743076 [DEBUG] switch_channel.c:3354 (sofia/internal/1003@124.123.68.233:10222) Callstate Change DOWN -> RINGING 2018-05-30 19:48:45.773076 [DEBUG] switch_ivr_originate.c:1278 Raw Codec Activation Success L16@48000hz 2 channel 20ms 2018-05-30 19:48:45.773076 [DEBUG] switch_core_codec.c:223 sofia/external/1000@139.59.19.72 Push codec L16:100 2018-05-30 19:48:45.773076 [DEBUG] switch_ivr_originate.c:1347 Play Ringback Tone [%(2000,4000,440,480)] recv 1159 bytes from tcp/[124.123.68.233]:10222 at 19:48:49.854699: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKr6g3ZcgBeFr8Q Contact: To: ;tag=b0260860 From: "Extension 1000" ;tag=03e14v3jr65Ua Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88 CSeq: 123518798 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp User-Agent: Z 5.2.14 rv2.8.88 Allow-Events: presence, kpml, talk Content-Length: 587 v=0 o=Z 0 1 IN IP4 10.144.160.39 s=Z c=IN IP4 10.144.160.39 t=0 0 m=audio 8000 RTP/AVP 102 9 3 111 0 8 97 110 112 96 98 101 100 99 a=rtpmap:102 opus/48000/2 a=fmtp:102 cbr=1; maxaveragebitrate=30000; useinbandfec=1 a=rtpmap:111 speex/16000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=rtpmap:110 speex/8000 a=rtpmap:112 speex/32000 a=rtpmap:96 G726-32/8000 a=rtpmap:98 telephone-event/48000 a=fmtp:98 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:100 telephone-event/16000 a=fmtp:100 0-16 a=rtpmap:99 telephone-event/32000 a=fmtp:99 0-16 a=sendrecv ------------------------------------------------------------------------ 2018-05-30 19:48:49.853075 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@124.123.68.233:10222 entering state [completing][200] 2018-05-30 19:48:49.853075 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=Z 0 1 IN IP4 10.144.160.39 s=Z c=IN IP4 10.144.160.39 t=0 0 m=audio 8000 RTP/AVP 102 9 3 111 0 8 97 110 112 96 98 101 100 99 a=rtpmap:102 opus/48000/2 a=fmtp:102 cbr=1; maxaveragebitrate=30000; useinbandfec=1 a=rtpmap:111 speex/16000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=rtpmap:110 speex/8000 a=rtpmap:112 speex/32000 a=rtpmap:96 G726-32/8000 a=rtpmap:98 telephone-event/48000 a=fmtp:98 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:100 telephone-event/16000 a=fmtp:100 0-16 a=rtpmap:99 telephone-event/32000 a=fmtp:99 0-16 send 449 bytes to tcp/[124.123.68.233]:10222 at 19:48:49.856059: ------------------------------------------------------------------------ ACK sip:1003@124.123.68.233:10222;transport=TCP SIP/2.0 Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKSFav170eBreUK Max-Forwards: 70 From: "Extension 1000" ;tag=03e14v3jr65Ua To: ;tag=b0260860 Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88 CSeq: 123518798 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:48:49.853075 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@124.123.68.233:10222 entering state [ready][200] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [speex:111:16000:20:0:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [iLBC:97:8000:30:0:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [speex:110:8000:20:0:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [speex:112:32000:20:0:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G726-32:96:8000:20:0:1]/[opus:116:48000:20:0:1] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5047 Set telephone-event payload to 98@48000 2018-05-30 19:48:49.853075 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps] 2018-05-30 19:48:49.853075 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps] 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:3446 Set Codec sofia/internal/1003@124.123.68.233:10222 opus/48000 20 ms 960 samples 0 bits 1 channels 2018-05-30 19:48:49.853075 [DEBUG] switch_core_codec.c:111 sofia/internal/1003@124.123.68.233:10222 Original read codec set to opus:116 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5390 Set telephone-event payload to 98@48000 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5448 sofia/internal/1003@124.123.68.233:10222 Set 2833 dtmf send payload to 98 recv payload to 101 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:8164 AUDIO RTP [sofia/internal/1003@124.123.68.233:10222] 159.89.163.195 port 21114 -> 10.144.160.39 port 8000 codec: 102 ms: 20 2018-05-30 19:48:49.853075 [DEBUG] switch_rtp.c:4189 Starting timer [soft] 960 bytes per 20ms 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:8468 sofia/internal/1003@124.123.68.233:10222 Set 2833 dtmf send payload to 98 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:8475 sofia/internal/1003@124.123.68.233:10222 Set 2833 dtmf receive payload to 101 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:8498 sofia/internal/1003@124.123.68.233:10222 Set rtp dtmf delay to 40 2018-05-30 19:48:49.853075 [NOTICE] sofia.c:8427 Channel [sofia/internal/1003@124.123.68.233:10222] has been answered 2018-05-30 19:48:49.853075 [DEBUG] switch_channel.c:3781 (sofia/internal/1003@124.123.68.233:10222) Callstate Change RINGING -> ACTIVE 2018-05-30 19:48:49.853075 [DEBUG] switch_core_codec.c:248 sofia/external/1000@139.59.19.72 Restore previous codec opus:116. 2018-05-30 19:48:49.853075 [DEBUG] switch_ivr_originate.c:3722 Originate Resulted in Success: [sofia/internal/1003@124.123.68.233:10222] 2018-05-30 19:48:49.853075 [DEBUG] switch_channel.c:2047 (sofia/external/1000@139.59.19.72) Callstate Change RING_WAIT -> ACTIVE 2018-05-30 19:48:49.853075 [DEBUG] switch_ivr_originate.c:3722 Originate Resulted in Success: [sofia/internal/1003@124.123.68.233:10222] 2018-05-30 19:48:49.853075 [DEBUG] switch_ivr_bridge.c:1744 (sofia/internal/1003@124.123.68.233:10222) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2018-05-30 19:48:49.853075 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 13) 2018-05-30 19:48:49.853075 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1003@124.123.68.233:10222) State EXCHANGE_MEDIA 2018-05-30 19:48:49.853075 [DEBUG] mod_sofia.c:645 SOFIA EXCHANGE_MEDIA 2018-05-30 19:48:49.873061 [DEBUG] switch_core_media.c:15475 Engaging Write Buffer at 3840 bytes to accommodate 3840->3840 send 751 bytes to udp/[139.59.19.72]:5060 at 19:48:49.881736: ------------------------------------------------------------------------ INFO sip:mod_sofia@139.59.19.72:5060 SIP/2.0 Via: SIP/2.0/UDP 159.89.163.195:5040;rport;branch=z9hG4bK77av27XeceyKN Max-Forwards: 70 From: ;tag=1SXBS74QmHctj To: "Extension 1000" ;tag=71jX784Kjc7Hr Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518800 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Outbound Call X-FS-Display-Number: 1003 ------------------------------------------------------------------------ recv 517 bytes from udp/[139.59.19.72]:5060 at 19:48:49.888236: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 159.89.163.195:5040;rport=5040;branch=z9hG4bK77av27XeceyKN From: ;tag=1SXBS74QmHctj To: "Extension 1000" ;tag=71jX784Kjc7Hr Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518800 INFO User-Agent: Shashi-switch-sip Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:48:49.913076 [DEBUG] switch_core_media.c:15475 Engaging Write Buffer at 1920 bytes to accommodate 1920->1920 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[239] Bytes encoded[36357] Encoded length ms[4780] Average encoded bitrate bps[72714] 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[237] PLC[0] FEC[0] 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[8] Bytes encoded[1408] Encoded length ms[160] Average encoded bitrate bps[0] 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[8] PLC[0] FEC[0] 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:50.793082 [INFO] switch_rtp.c:7333 Auto Changing audio port from 10.144.160.39:8000 to 124.123.68.233:10231 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[9] Bytes encoded[1243] Encoded length ms[180] Average encoded bitrate bps[0] 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[9] PLC[0] FEC[0] 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[19] Bytes encoded[2245] Encoded length ms[380] Average encoded bitrate bps[0] 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[19] PLC[0] FEC[0] 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[53] Bytes encoded[10088] Encoded length ms[1060] Average encoded bitrate bps[80704] 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[53] PLC[0] FEC[0] 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[261] Bytes encoded[58017] Encoded length ms[5220] Average encoded bitrate bps[92827] 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[259] PLC[0] FEC[0] 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[23] Bytes encoded[3966] Encoded length ms[460] Average encoded bitrate bps[0] 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[23] PLC[0] FEC[0] 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[195] Bytes encoded[42168] Encoded length ms[3900] Average encoded bitrate bps[112448] 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[195] PLC[0] FEC[0] 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[137] Bytes encoded[26772] Encoded length ms[2740] Average encoded bitrate bps[107088] 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[137] PLC[0] FEC[0] 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[56] Bytes encoded[10841] Encoded length ms[1120] Average encoded bitrate bps[86728] 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[56] PLC[0] FEC[0] 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[17] Bytes encoded[3572] Encoded length ms[340] Average encoded bitrate bps[0] 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[17] PLC[0] FEC[0] 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[81] Bytes encoded[13269] Encoded length ms[1620] Average encoded bitrate bps[106152] 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[81] PLC[0] FEC[0] 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[41] Bytes encoded[6703] Encoded length ms[820] Average encoded bitrate bps[0] 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[41] PLC[0] FEC[0] 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[304] Bytes encoded[57137] Encoded length ms[6080] Average encoded bitrate bps[76182] 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[304] PLC[0] FEC[0] 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[345] Bytes encoded[72122] Encoded length ms[6900] Average encoded bitrate bps[96162] 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[341] PLC[0] FEC[0] 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[64] Bytes encoded[9565] Encoded length ms[1280] Average encoded bitrate bps[76520] 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[64] PLC[0] FEC[0] 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[299] Bytes encoded[58216] Encoded length ms[5980] Average encoded bitrate bps[93145] 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[295] PLC[0] FEC[0] 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[94] Bytes encoded[17986] Encoded length ms[1880] Average encoded bitrate bps[143888] 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[94] PLC[0] FEC[0] 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[34] Bytes encoded[5569] Encoded length ms[680] Average encoded bitrate bps[0] 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[34] PLC[0] FEC[0] 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[25] Bytes encoded[3857] Encoded length ms[500] Average encoded bitrate bps[0] 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[25] PLC[0] FEC[0] 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[73] Bytes encoded[13469] Encoded length ms[1460] Average encoded bitrate bps[107752] 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[73] PLC[0] FEC[0] 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[165] Bytes encoded[26370] Encoded length ms[3300] Average encoded bitrate bps[70320] 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[165] PLC[0] FEC[0] 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[79] Bytes encoded[13171] Encoded length ms[1580] Average encoded bitrate bps[105368] 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[79] PLC[0] FEC[0] 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] recv 1361 bytes from udp/[139.59.19.72]:5060 at 19:49:40.276099: ------------------------------------------------------------------------ INVITE sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0 Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKvy3DZp7rFc1vS Max-Forwards: 69 From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518799 INVITE Contact: User-Agent: Shashi-switch-sip Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Session-Expires: 120;refresher=uac Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 491 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1000" ;party=calling;screen=yes;privacy=off v=0 o=Shashi-switch-sdp 1527689106 1527689107 IN IP4 139.59.19.72 s=Shashi-switch-sdp c=IN IP4 139.59.19.72 t=0 0 m=audio 20616 RTP/AVP 102 103 9 0 8 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 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=ptime:20 ------------------------------------------------------------------------ send 419 bytes to udp/[139.59.19.72]:5060 at 19:49:40.281520: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKvy3DZp7rFc1vS From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518799 INVITE User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:49:40.273085 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [received][100] 2018-05-30 19:49:40.273085 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=Shashi-switch-sdp 1527689106 1527689107 IN IP4 139.59.19.72 s=Shashi-switch-sdp c=IN IP4 139.59.19.72 t=0 0 m=audio 20616 RTP/AVP 102 103 9 0 8 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 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=ptime:20 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[opus:116:48000:20:0:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[G722:9:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMU:0:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMA:8:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5047 Set telephone-event payload to 103@48000 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5390 Set telephone-event payload to 103@48000 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5448 sofia/external/1000@139.59.19.72 Set 2833 dtmf send payload to 103 recv payload to 103 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:8147 Audio params are unchanged for sofia/external/1000@139.59.19.72. 2018-05-30 19:49:40.273085 [DEBUG] sofia.c:8206 Processing updated SDP send 1049 bytes to udp/[139.59.19.72]:5060 at 19:49:40.282310: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKvy3DZp7rFc1vS From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518799 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 120;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 305 v=0 o=FreeSWITCH 1527681426 1527681427 IN IP4 159.89.163.195 s=FreeSWITCH c=IN IP4 159.89.163.195 t=0 0 m=audio 28298 RTP/AVP 102 103 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=ptime:20 ------------------------------------------------------------------------ 2018-05-30 19:49:40.273085 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [completed][200] recv 441 bytes from udp/[139.59.19.72]:5060 at 19:49:40.302574: ------------------------------------------------------------------------ ACK sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0 Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKX7v60HrvcNQFN Max-Forwards: 70 From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518799 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:49:40.313079 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [ready][200] 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[411] Bytes encoded[88491] Encoded length ms[8220] Average encoded bitrate bps[88491] 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[395] PLC[0] FEC[0] 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[42] Bytes encoded[7807] Encoded length ms[840] Average encoded bitrate bps[0] 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[42] PLC[0] FEC[0] 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[550] Bytes encoded[121681] Encoded length ms[11000] Average encoded bitrate bps[88495] 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[544] PLC[0] FEC[0] 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[76] Bytes encoded[16898] Encoded length ms[1520] Average encoded bitrate bps[135184] 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[76] PLC[0] FEC[0] 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps] recv 619 bytes from udp/[139.59.19.72]:5060 at 19:50:09.585677: ------------------------------------------------------------------------ BYE sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0 Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bK028g62a73Ft7Q Max-Forwards: 70 From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518800 BYE User-Agent: Shashi-switch-sip Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:50:09.593068 [NOTICE] sofia.c:1079 Hangup sofia/external/1000@139.59.19.72 [CS_EXECUTE] [NORMAL_CLEARING] send 536 bytes to udp/[139.59.19.72]:5060 at 19:50:09.601292: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bK028g62a73Ft7Q From: "Extension 1000" ;tag=71jX784Kjc7Hr To: ;tag=1SXBS74QmHctj Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e CSeq: 123518800 BYE User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:50:09.593068 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/external/1000@139.59.19.72] 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_bridge.c:825 sofia/external/1000@139.59.19.72 ending bridge by request from write function 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/1003@124.123.68.233:10222] 2018-05-30 19:50:09.613060 [NOTICE] switch_ivr_bridge.c:1034 Hangup sofia/internal/1003@124.123.68.233:10222 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1003@124.123.68.233:10222) State EXCHANGE_MEDIA going to sleep 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_HANGUP (Cur 2 Tot 13) 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1003@124.123.68.233:10222) Callstate Change ACTIVE -> HANGUP 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1003@124.123.68.233:10222) State HANGUP 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:443 sofia/internal/1003@124.123.68.233:10222 Overriding SIP cause 480 with 200 from the other leg 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1003@124.123.68.233:10222 hanging up, cause: NORMAL_CLEARING 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/1003@124.123.68.233:10222 send 658 bytes to tcp/[124.123.68.233]:10222 at 19:50:09.618167: ------------------------------------------------------------------------ BYE sip:1003@124.123.68.233:10222;transport=TCP SIP/2.0 Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKtr3m32Hj804DF Max-Forwards: 70 From: "Extension 1000" ;tag=03e14v3jr65Ua To: ;tag=b0260860 Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88 CSeq: 123518799 BYE User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1003@124.123.68.233:10222 Standard HANGUP, cause: NORMAL_CLEARING 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1003@124.123.68.233:10222) State HANGUP going to sleep 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1003@124.123.68.233:10222) State Change CS_HANGUP -> CS_REPORTING 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_REPORTING (Cur 2 Tot 13) 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1003@124.123.68.233:10222) State REPORTING 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1003@124.123.68.233:10222 Standard REPORTING, cause: NORMAL_CLEARING 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1003@124.123.68.233:10222) State REPORTING going to sleep 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1003@124.123.68.233:10222) State Change CS_REPORTING -> CS_DESTROY 2018-05-30 19:50:09.613060 [DEBUG] switch_core_session.c:1713 Session 13 (sofia/internal/1003@124.123.68.233:10222) Locked, Waiting on external entities 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_bridge.c:1846 sofia/external/1000@139.59.19.72 skip receive message [TRANSFER] (channel is hungup already) 2018-05-30 19:50:09.613060 [DEBUG] switch_core_session.c:2885 sofia/external/1000@139.59.19.72 skip receive message [PHONE_EVENT] (channel is hungup already) 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1000@139.59.19.72) State EXECUTE going to sleep 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_HANGUP (Cur 2 Tot 13) 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_async.c:1324 Stop recording file /usr/local/freeswitch/recordings/2018-05-30-19-48-44_1001_1000.wav 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_async.c:1388 Channel is hung up 2018-05-30 19:50:09.613060 [DEBUG] switch_core_media_bug.c:1315 Removing BUG from sofia/external/1000@139.59.19.72 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:850 (sofia/external/1000@139.59.19.72) Callstate Change ACTIVE -> HANGUP 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1000@139.59.19.72) State HANGUP 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:449 Channel sofia/external/1000@139.59.19.72 hanging up, cause: NORMAL_CLEARING 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:60 sofia/external/1000@139.59.19.72 Standard HANGUP, cause: NORMAL_CLEARING 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1000@139.59.19.72) State HANGUP going to sleep 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:619 (sofia/external/1000@139.59.19.72) State Change CS_HANGUP -> CS_REPORTING 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_REPORTING (Cur 2 Tot 13) 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1000@139.59.19.72) State REPORTING 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:174 sofia/external/1000@139.59.19.72 Standard REPORTING, cause: NORMAL_CLEARING 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1000@139.59.19.72) State REPORTING going to sleep 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:610 (sofia/external/1000@139.59.19.72) State Change CS_REPORTING -> CS_DESTROY 2018-05-30 19:50:09.613060 [DEBUG] switch_core_session.c:1713 Session 12 (sofia/external/1000@139.59.19.72) Locked, Waiting on external entities 2018-05-30 19:50:09.613060 [NOTICE] switch_core_session.c:1731 Session 12 (sofia/external/1000@139.59.19.72) Ended 2018-05-30 19:50:09.613060 [NOTICE] switch_core_session.c:1735 Close Channel sofia/external/1000@139.59.19.72 [CS_DESTROY] 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:741 (sofia/external/1000@139.59.19.72) Running State Change CS_DESTROY (Cur 1 Tot 13) 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1000@139.59.19.72) State DESTROY 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:354 sofia/external/1000@139.59.19.72 SOFIA DESTROY 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[450] PLC[0] FEC[0] 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[493] Bytes encoded[110276] Encoded length ms[9860] Average encoded bitrate bps[98023] 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:181 sofia/external/1000@139.59.19.72 Standard DESTROY 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1000@139.59.19.72) State DESTROY going to sleep 2018-05-30 19:50:09.613060 [NOTICE] switch_core_session.c:1731 Session 13 (sofia/internal/1003@124.123.68.233:10222) Ended 2018-05-30 19:50:09.613060 [NOTICE] switch_core_session.c:1735 Close Channel sofia/internal/1003@124.123.68.233:10222 [CS_DESTROY] 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_DESTROY (Cur 0 Tot 13) 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1003@124.123.68.233:10222) State DESTROY 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:354 sofia/internal/1003@124.123.68.233:10222 SOFIA DESTROY 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[3989] PLC[0] FEC[0] 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[79] Bytes encoded[2549] Encoded length ms[1580] Average encoded bitrate bps[20392] 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[3912] Bytes encoded[462071] Encoded length ms[78240] Average encoded bitrate bps[47391] 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1003@124.123.68.233:10222 Standard DESTROY 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1003@124.123.68.233:10222) State DESTROY going to sleep recv 417 bytes from tcp/[124.123.68.233]:10222 at 19:50:09.704040: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKtr3m32Hj804DF Contact: To: ;tag=b0260860 From: "Extension 1000" ;tag=03e14v3jr65Ua Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88 CSeq: 123518799 BYE User-Agent: Z 5.2.14 rv2.8.88 Content-Length: 0 ------------------------------------------------------------------------ freeswitch@debian-s-1vcpu-1gb-blr1-01> ...