2017-08-13 19:38:38.361522 [NOTICE] switch_channel.c:1104 New Channel sofia/external/1010@10.240.0.23 [00e94e72-805f-11e7-b4fa-b1e4f221b370] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_NEW (Cur 1 Tot 382) 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:9873 sofia/external/1010@10.240.0.23 receiving invite from 39.40.173.218:2429 version: 1.6.19 64bit 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:7084 Channel sofia/external/1010@10.240.0.23 entering state [received][100] 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=Z 0 0 IN IP4 192.168.10.7 s=Z c=IN IP4 192.168.10.7 t=0 0 m=audio 35696 RTP/AVP 3 110 8 0 97 101 a=rtpmap:110 speex/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:7486 (sofia/external/1010@10.240.0.23) State Change CS_NEW -> CS_INIT 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:603 (sofia/external/1010@10.240.0.23) State NEW 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_INIT (Cur 1 Tot 382) 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1010@10.240.0.23) State INIT 2017-08-13 19:38:38.361522 [DEBUG] mod_sofia.c:90 sofia/external/1010@10.240.0.23 SOFIA INIT 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:40 sofia/external/1010@10.240.0.23 Standard INIT 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:48 (sofia/external/1010@10.240.0.23) State Change CS_INIT -> CS_ROUTING 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1010@10.240.0.23) State INIT going to sleep 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_ROUTING (Cur 1 Tot 382) 2017-08-13 19:38:38.361522 [DEBUG] switch_channel.c:2249 (sofia/external/1010@10.240.0.23) Callstate Change DOWN -> RINGING 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1010@10.240.0.23) State ROUTING 2017-08-13 19:38:38.361522 [DEBUG] mod_sofia.c:143 sofia/external/1010@10.240.0.23 SOFIA ROUTING 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:236 sofia/external/1010@10.240.0.23 Standard ROUTING 2017-08-13 19:38:38.361522 [INFO] mod_dialplan_xml.c:637 Processing 1010 <1010>->9978 in context public Dialplan: sofia/external/1010@10.240.0.23 parsing [public->fax_receive] continue=false Dialplan: sofia/external/1010@10.240.0.23 Regex (PASS) [fax_receive] destination_number(9978) =~ /^9978$/ break=on-false Dialplan: sofia/external/1010@10.240.0.23 Action answer() Dialplan: sofia/external/1010@10.240.0.23 Action playback(silence_stream://2000) Dialplan: sofia/external/1010@10.240.0.23 Action set(fax_enable_t38_request=true) Dialplan: sofia/external/1010@10.240.0.23 Action set(fax_enable_t38=true) Dialplan: sofia/external/1010@10.240.0.23 Action rxfax(/tmp/FAX-${uuid}.tif) Dialplan: sofia/external/1010@10.240.0.23 Action hangup() 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:286 (sofia/external/1010@10.240.0.23) State Change CS_ROUTING -> CS_EXECUTE 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1010@10.240.0.23) State ROUTING going to sleep 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_EXECUTE (Cur 1 Tot 382) 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1010@10.240.0.23) State EXECUTE 2017-08-13 19:38:38.361522 [DEBUG] mod_sofia.c:198 sofia/external/1010@10.240.0.23 SOFIA EXECUTE 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:328 sofia/external/1010@10.240.0.23 Standard EXECUTE EXECUTE sofia/external/1010@10.240.0.23 answer() 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[G722:9:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[G722:9:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMU:0:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMA:8:8000:20:64000:1] 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:3061 Set Codec sofia/external/1010@10.240.0.23 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2017-08-13 19:38:38.361522 [DEBUG] switch_core_codec.c:111 sofia/external/1010@10.240.0.23 Original read codec set to PCMA:8 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4767 sofia/external/1010@10.240.0.23 Set 2833 dtmf send payload to 101 recv payload to 101 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/external/1010@10.240.0.23] 10.240.0.23 port 20362 -> 192.168.10.7 port 35696 codec: 8 ms: 20 2017-08-13 19:38:38.361522 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:7179 sofia/external/1010@10.240.0.23 Set 2833 dtmf send payload to 101 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:7186 sofia/external/1010@10.240.0.23 Set 2833 dtmf receive payload to 101 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:7209 sofia/external/1010@10.240.0.23 Set rtp dtmf delay to 40 2017-08-13 19:38:38.361522 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/1010@10.240.0.23! 2017-08-13 19:38:38.361522 [DEBUG] switch_channel.c:3474 (sofia/external/1010@10.240.0.23) Callstate Change RINGING -> EARLY 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/external/1010@10.240.0.23. 2017-08-13 19:38:38.361522 [DEBUG] mod_sofia.c:850 Local SDP sofia/external/1010@10.240.0.23: v=0 o=FreeSWITCH 1502632756 1502632757 IN IP4 35.197.168.74 s=FreeSWITCH c=IN IP4 35.197.168.74 t=0 0 m=audio 20362 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:7084 Channel sofia/external/1010@10.240.0.23 entering state [completed][200] 2017-08-13 19:38:38.361522 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/1010@10.240.0.23] has been answered 2017-08-13 19:38:38.361522 [DEBUG] switch_channel.c:3773 (sofia/external/1010@10.240.0.23) Callstate Change EARLY -> ACTIVE EXECUTE sofia/external/1010@10.240.0.23 playback(silence_stream://2000) 2017-08-13 19:38:38.361522 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-08-13 19:38:38.861527 [DEBUG] sofia.c:7084 Channel sofia/external/1010@10.240.0.23 entering state [ready][200] 2017-08-13 19:38:39.341525 [INFO] switch_rtp.c:7231 Auto Changing audio port from 192.168.10.7:35696 to 39.40.173.218:35696 2017-08-13 19:38:39.341525 [DEBUG] sofia.c:7084 Channel sofia/external/1010@10.240.0.23 entering state [received][100] 2017-08-13 19:38:39.341525 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=Z 0 1 IN IP4 192.168.10.7 s=Z c=IN IP4 192.168.10.7 t=0 0 m=image 35696 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy 2017-08-13 19:38:39.341525 [DEBUG] switch_core_media.c:4041 sofia/external/1010@10.240.0.23 T38 ACCEPT on request 2017-08-13 19:38:39.341525 [DEBUG] switch_core_media.c:4146 sofia/external/1010@10.240.0.23 T38 IS NOT POSSIBLE on request 2017-08-13 19:38:39.341525 [DEBUG] sofia.c:8007 Reinvite resulted in codec negotiation failure. 2017-08-13 19:38:39.341525 [DEBUG] sofia.c:7077 Channel sofia/external/1010@10.240.0.23 skipping state [ready][488] 2017-08-13 19:38:40.341523 [NOTICE] sofia.c:1012 Hangup sofia/external/1010@10.240.0.23 [CS_EXECUTE] [NORMAL_CLEARING] 2017-08-13 19:38:40.341523 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://2000 2017-08-13 19:38:40.341523 [DEBUG] switch_core_session.c:2815 sofia/external/1010@10.240.0.23 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1010@10.240.0.23) State EXECUTE going to sleep 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_HANGUP (Cur 1 Tot 382) 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:850 (sofia/external/1010@10.240.0.23) Callstate Change ACTIVE -> HANGUP 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1010@10.240.0.23) State HANGUP 2017-08-13 19:38:40.341523 [DEBUG] mod_sofia.c:438 Channel sofia/external/1010@10.240.0.23 hanging up, cause: NORMAL_CLEARING 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:60 sofia/external/1010@10.240.0.23 Standard HANGUP, cause: NORMAL_CLEARING 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1010@10.240.0.23) State HANGUP going to sleep 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:619 (sofia/external/1010@10.240.0.23) State Change CS_HANGUP -> CS_REPORTING 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_REPORTING (Cur 1 Tot 382) 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1010@10.240.0.23) State REPORTING 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:174 sofia/external/1010@10.240.0.23 Standard REPORTING, cause: NORMAL_CLEARING 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1010@10.240.0.23) State REPORTING going to sleep 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:610 (sofia/external/1010@10.240.0.23) State Change CS_REPORTING -> CS_DESTROY 2017-08-13 19:38:40.341523 [DEBUG] switch_core_session.c:1665 Session 382 (sofia/external/1010@10.240.0.23) Locked, Waiting on external entities 2017-08-13 19:38:40.341523 [NOTICE] switch_core_session.c:1683 Session 382 (sofia/external/1010@10.240.0.23) Ended 2017-08-13 19:38:40.341523 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/1010@10.240.0.23 [CS_DESTROY] 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:741 (sofia/external/1010@10.240.0.23) Running State Change CS_DESTROY (Cur 0 Tot 382) 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1010@10.240.0.23) State DESTROY 2017-08-13 19:38:40.341523 [DEBUG] mod_sofia.c:343 sofia/external/1010@10.240.0.23 SOFIA DESTROY 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:181 sofia/external/1010@10.240.0.23 Standard DESTROY 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1010@10.240.0.23) State DESTROY going to sleep