- 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