1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.310072 [NOTICE] switch_channel.c:1104 New Channel sofia/external/1234 [1cd39dcf-bccc-4a25-9f9d-9b75edb4c938] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.310072 [DEBUG] mod_sofia.c:4819 (sofia/external/1234) State Change CS_NEW -> CS_INIT 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1234) Running State Change CS_INIT (Cur 1 Tot 2) 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1234) State INIT 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] mod_sofia.c:90 sofia/external/1234 SOFIA INIT 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] sofia_glue.c:1295 sofia/external/1234 sending invite version: 1.6.18 git 628f1bd 2017-07-06 18:33:44Z 64bit 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 Local SDP: 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 v=0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 o=FreeSWITCH 1510112840 1510112841 IN IP4 10.10.30.24 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 s=FreeSWITCH 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 c=IN IP4 10.10.30.24 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 t=0 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 m=audio 56716 RTP/AVP 0 101 13 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=rtpmap:0 PCMU/8000 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=rtpmap:101 telephone-event/8000 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=fmtp:101 0-16 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=rtpmap:13 CN/8000 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=ptime:20 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=sendrecv 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 send 1055 bytes to udp/[10.10.101.96]:5060 at 19:32:36.335074: ------------------------------------------------------------------------ INVITE sip:1234@10.10.101.96 SIP/2.0 Via: SIP/2.0/UDP 10.10.30.24:5080;rport;branch=z9hG4bK8pemXF8Fc9y7H Max-Forwards: 70 From: "" ;tag=6v0DjeHDX2pcD To: Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 114748714 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.18+git~20170706T183344Z~628f1bd44c~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 242 X-FS-Support: update_display,send_info Remote-Party-ID: ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1510112840 1510112841 IN IP4 10.10.30.24 s=FreeSWITCH c=IN IP4 10.10.30.24 t=0 0 m=audio 56716 RTP/AVP 0 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 ------------------------------------------------------------------------ 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:40 sofia/external/1234 Standard INIT 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:48 (sofia/external/1234) State Change CS_INIT -> CS_ROUTING 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1234) State INIT going to sleep 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1234) Running State Change CS_ROUTING (Cur 1 Tot 2) 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] sofia.c:7048 Channel sofia/external/1234 entering state [calling][0] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1234) State ROUTING 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] mod_sofia.c:143 sofia/external/1234 SOFIA ROUTING 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_ivr_originate.c:67 (sofia/external/1234) State Change CS_ROUTING -> CS_CONSUME_MEDIA 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1234) State ROUTING going to sleep 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1234) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 2) 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:662 (sofia/external/1234) State CONSUME_MEDIA 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.331074 [DEBUG] switch_core_state_machine.c:662 (sofia/external/1234) State CONSUME_MEDIA going to sleep recv 403 bytes from udp/[10.10.101.96]:5060 at 19:32:36.348075: ------------------------------------------------------------------------ SIP/2.0 180 Ringing From: "";tag=6v0DjeHDX2pcD To: ;tag=8e901d0-0-13c4-55013-1d0029-25e5412a-1d0029 Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 114748714 INVITE Via: SIP/2.0/UDP 10.10.30.24:5080;rport=5080;branch=z9hG4bK8pemXF8Fc9y7H Supported: 100rel User-Agent: Brktsip/6.3.2B8 (Dialogic) Contact: Content-Length: 0 ------------------------------------------------------------------------ recv 579 bytes from udp/[10.10.101.96]:5060 at 19:32:36.349075: ------------------------------------------------------------------------ SIP/2.0 200 OK From: "";tag=6v0DjeHDX2pcD To: ;tag=8e901d0-0-13c4-55013-1d0029-25e5412a-1d0029 Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 114748714 INVITE Via: SIP/2.0/UDP 10.10.30.24:5080;rport=5080;branch=z9hG4bK8pemXF8Fc9y7H Supported: 100rel User-Agent: Brktsip/6.3.2B8 (Dialogic) Contact: Content-Type: application/sdp Content-Length: 148 v=0 o=- 2210889541 0820743000 IN IP4 10.10.101.96 s=no_session_name t=0 0 m=audio 56383 RTP/AVP 0 c=IN IP4 10.10.101.96 a=rtpmap:0 PCMU/8000 ------------------------------------------------------------------------ 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.370076 [DEBUG] sofia.c:7048 Channel sofia/external/1234 entering state [proceeding][180] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.370076 [NOTICE] sofia.c:7156 Ring-Ready sofia/external/1234! 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.370076 [DEBUG] switch_channel.c:3346 (sofia/external/1234) Callstate Change DOWN -> RINGING 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] sofia.c:7048 Channel sofia/external/1234 entering state [completing][200] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] sofia.c:7058 Remote SDP: 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 v=0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 o=- 2210889541 820743000 IN IP4 10.10.101.96 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 s=no_session_name 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 t=0 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 m=audio 56383 RTP/AVP 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 c=IN IP4 10.10.101.96 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=rtpmap:0 PCMU/8000 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 send 414 bytes to udp/[10.10.101.96]:5060 at 19:32:36.419079: ------------------------------------------------------------------------ ACK sip:10.10.101.96 SIP/2.0 Via: SIP/2.0/UDP 10.10.30.24:5080;rport;branch=z9hG4bK9Z7cZaSK9HNtD Max-Forwards: 70 From: "" ;tag=6v0DjeHDX2pcD To: ;tag=8e901d0-0-13c4-55013-1d0029-25e5412a-1d0029 Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 114748714 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] sofia.c:7048 Channel sofia/external/1234 entering state [ready][200] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] switch_core_media.c:3057 Set Codec sofia/external/1234 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] switch_core_codec.c:111 sofia/external/1234 Original read codec set to PCMU:0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] switch_core_media.c:4770 No 2833 in SDP. Disable 2833 dtmf and switch to INFO 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] switch_core_media.c:6874 AUDIO RTP [sofia/external/1234] 10.10.30.24 port 56716 -> 10.10.101.96 port 56383 codec: 0 ms: 20 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.410078 [DEBUG] switch_rtp.c:4108 Starting timer [soft] 160 bytes per 20ms 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.430079 [DEBUG] switch_core_media.c:7205 sofia/external/1234 Set rtp dtmf delay to 40 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.430079 [NOTICE] sofia.c:8182 Channel [sofia/external/1234] has been answered 2017-11-08 13:32:36.430079 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/external/1234] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.450080 [INFO] switch_channel.c:3129 sofia/external/1234 Flipping CID from "" <0000000000> to "Outbound Call" <1234> 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.450080 [DEBUG] mod_commands.c:4845 (sofia/external/1234) State Change CS_CONSUME_MEDIA -> CS_EXECUTE 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.450080 [DEBUG] switch_channel.c:3773 (sofia/external/1234) Callstate Change RINGING -> ACTIVE 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.470082 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1234) Running State Change CS_EXECUTE (Cur 1 Tot 2) 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.470082 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1234) State EXECUTE 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.470082 [DEBUG] mod_sofia.c:198 sofia/external/1234 SOFIA EXECUTE 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.470082 [DEBUG] switch_core_state_machine.c:328 sofia/external/1234 Standard EXECUTE 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 EXECUTE sofia/external/1234 txfax(c:/streem/documents/test1.tif) 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.470082 [DEBUG] mod_spandsp_fax.c:1503 Raw read codec activation Success L16 20000 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.470082 [DEBUG] switch_core_codec.c:223 sofia/external/1234 Push codec L16:100 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.470082 [DEBUG] mod_spandsp_fax.c:1521 Raw write codec activation Success L16 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.530085 [DEBUG] switch_rtp.c:7254 Correct audio ip/port confirmed. 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:36.750098 [DEBUG] mod_spandsp_fax.c:277 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:38.510198 [DEBUG] mod_spandsp_fax.c:277 FLOW T.30 HDLC signal status is Carrier down (-1) in state T recv 796 bytes from udp/[10.10.101.96]:5060 at 19:32:39.464253: ------------------------------------------------------------------------ INVITE sip:gw+10.10.101.96@10.10.30.24:5080;transport=udp;gw=10.10.101.96 SIP/2.0 From: ;tag=8e901d0-0-13c4-55013-1d0029-25e5412a-1d0029 To: "";tag=6v0DjeHDX2pcD Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 1 INVITE Via: SIP/2.0/UDP 10.10.101.96:5060;branch=z9hG4bK-1d002c-7148ad8c-34bef768 Supported: 100rel Max-Forwards: 70 User-Agent: Brktsip/6.3.2B8 (Dialogic) Contact: Content-Type: application/sdp Content-Length: 286 v=0 o=- 2210889541 0934851000 IN IP4 10.10.101.96 s=no_session_name t=0 0 m=image 56383 udptl t38 c=IN IP4 10.10.101.96 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:72 a=T38FaxUdpEC:t38UDPRedundancy ------------------------------------------------------------------------ send 387 bytes to udp/[10.10.101.96]:5060 at 19:32:39.466253: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.101.96:5060;branch=z9hG4bK-1d002c-7148ad8c-34bef768 From: ;tag=8e901d0-0-13c4-55013-1d0029-25e5412a-1d0029 To: "";tag=6v0DjeHDX2pcD Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.18+git~20170706T183344Z~628f1bd44c~64bit Content-Length: 0 ------------------------------------------------------------------------ 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.470253 [DEBUG] sofia.c:7048 Channel sofia/external/1234 entering state [received][100] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.470253 [DEBUG] sofia.c:7058 Remote SDP: 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 v=0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 o=- 2210889541 934851000 IN IP4 10.10.101.96 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 s=no_session_name 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 t=0 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 m=image 56383 udptl t38 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 c=IN IP4 10.10.101.96 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=T38FaxVersion:0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=T38MaxBitRate:14400 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=T38FaxRateManagement:transferredTCF 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=T38FaxMaxBuffer:200 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=T38FaxMaxDatagram:72 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 a=T38FaxUdpEC:t38UDPRedundancy 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] switch_core_media.c:4037 sofia/external/1234 T38 ACCEPT on request 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] switch_core_media.c:4142 sofia/external/1234 T38 IS POSSIBLE on request 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1072 T38 SDP Origin = - 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1073 T38FaxVersion = 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1074 T38MaxBitRate = 14400 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1075 T38FaxFillBitRemoval = 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1076 T38FaxTranscodingMMR = 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1077 T38FaxTranscodingJBIG = 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1078 T38FaxRateManagement = transferredTCF 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1079 T38FaxMaxBuffer = 200 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1080 T38FaxMaxDatagram = 72 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1081 T38FaxUdpEC = t38UDPRedundancy 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1082 T38VendorInfo = 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1083 ip = 10.10.101.96 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] mod_spandsp_fax.c:1085 port = 56383 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:32:39.490254 [DEBUG] switch_core_media.c:9746 Remote address:port [10.10.101.96:56383] has not changed. 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:277 FLOW T.30 T0 expired in state T 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:277 FLOW T.30 Status changing to Timed out waiting for initial communication 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:524 ============================================================================== 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:536 Fax processing not successful - result (2) Timed out waiting for initial communication. 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:541 Remote station id: 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:542 Local station id: xStreem 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:543 Pages transferred: 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:545 Total fax pages: 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:546 Image resolution: 0x0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:547 Transfer Rate: 14400 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:549 ECM status off 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:550 remote country: 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:551 remote vendor: 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:552 remote model: 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.489686 [DEBUG] mod_spandsp_fax.c:554 ============================================================================== 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.509687 [DEBUG] mod_spandsp_fax.c:277 FLOW T.30 Changing from state T to CALL_FINISHED 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.509687 [DEBUG] mod_spandsp_fax.c:277 FLOW T.30 Changing from phase A_CNG to CALL_FINISHED 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.509687 [DEBUG] mod_spandsp_fax.c:277 FLOW T.38T Set rx type 9 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.509687 [DEBUG] mod_spandsp_fax.c:277 FLOW T.38T Set tx type 9 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.509687 [DEBUG] mod_spandsp_fax.c:277 FLOW T.38T FAX exchange complete 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.509687 [DEBUG] mod_spandsp_fax.c:277 FLOW T.30 Call completed 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.509687 [DEBUG] switch_core_codec.c:248 sofia/external/1234 Restore previous codec PCMU:0. 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.509687 [NOTICE] switch_core_state_machine.c:385 sofia/external/1234 has executed the last dialplan instruction, hanging up. 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.509687 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/external/1234 [CS_EXECUTE] [NORMAL_CLEARING] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1234) State EXECUTE going to sleep 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1234) Running State Change CS_HANGUP (Cur 1 Tot 2) 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:850 (sofia/external/1234) Callstate Change ACTIVE -> HANGUP 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1234) State HANGUP 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] mod_sofia.c:438 Channel sofia/external/1234 hanging up, cause: NORMAL_CLEARING 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/external/1234 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:60 sofia/external/1234 Standard HANGUP, cause: NORMAL_CLEARING 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1234) State HANGUP going to sleep send 585 bytes to udp/[10.10.101.96]:5060 at 19:33:39.534689: ------------------------------------------------------------------------ 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:619 (sofia/external/1234) State Change CS_HANGUP -> CS_REPORTING BYE sip:10.10.101.96 SIP/2.0 Via: SIP/2.0/UDP 10.10.30.24:5080;rport;branch=z9hG4bKa905059p6tBDS1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1234) Running State Change CS_REPORTING (Cur 1 Tot 2) Max-Forwards: 70 From: "" ;tag=6v0DjeHDX2pcD To: ;tag=8e901d0-0-13c4-55013-1d0029-25e5412a-1d0029 Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 114748715 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.18+git~20170706T183344Z~628f1bd44c~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ send 539 bytes to udp/[10.10.101.96]:5060 at 19:33:39.535689: ------------------------------------------------------------------------ SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 10.10.101.96:5060;branch=z9hG4bK-1d002c-7148ad8c-34bef768 From: ;tag=8e901d0-0-13c4-55013-1d0029-25e5412a-1d0029 To: "";tag=6v0DjeHDX2pcD Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.18+git~20170706T183344Z~628f1bd44c~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1234) State REPORTING ------------------------------------------------------------------------ 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:174 sofia/external/1234 Standard REPORTING, cause: NORMAL_CLEARING 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1234) State REPORTING going to sleep recv 366 bytes from udp/[10.10.101.96]:5060 at 19:33:39.536689: ------------------------------------------------------------------------ SIP/2.0 200 OK From: "";tag=6v0DjeHDX2pcD To: ;tag=8e901d0-0-13c4-55013-1d0029-25e5412a-1d0029 Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 114748715 BYE Via: SIP/2.0/UDP 10.10.30.24:5080;rport=5080;branch=z9hG4bKa905059p6tBDS Supported: 100rel User-Agent: Brktsip/6.3.2B8 (Dialogic) Content-Length: 0 ------------------------------------------------------------------------ recv 383 bytes from udp/[10.10.101.96]:5060 at 19:33:39.538689: ------------------------------------------------------------------------ ACK sip:gw+10.10.101.96@10.10.30.24:5080;transport=udp;gw=10.10.101.96 SIP/2.0 From: ;tag=8e901d0-0-13c4-55013-1d0029-25e5412a-1d0029 To: "";tag=6v0DjeHDX2pcD Call-ID: 6a6ec2d6-3f5e-1236-2795-8d8a610f888f CSeq: 1 ACK Via: SIP/2.0/UDP 10.10.101.96:5060;branch=z9hG4bK-1d002c-7148ad8c-34bef768 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:610 (sofia/external/1234) State Change CS_REPORTING -> CS_DESTROY 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_session.c:1664 Session 2 (sofia/external/1234) Locked, Waiting on external entities 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [NOTICE] switch_core_session.c:1682 Session 2 (sofia/external/1234) Ended 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [NOTICE] switch_core_session.c:1686 Close Channel sofia/external/1234 [CS_DESTROY] 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:741 (sofia/external/1234) Running State Change CS_DESTROY (Cur 0 Tot 2) 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1234) State DESTROY 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] mod_sofia.c:343 sofia/external/1234 SOFIA DESTROY 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:181 sofia/external/1234 Standard DESTROY 1cd39dcf-bccc-4a25-9f9d-9b75edb4c938 2017-11-08 13:33:39.529688 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1234) State DESTROY going to sleep