Sending the fax: originate {fax_verbose=true}sofia/gateway/CS2K/939165135 &txfax(/root/txfax.tiff) LOG: 2017-11-24 18:29:32.325313 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables 2017-11-24 18:29:32.325313 [NOTICE] switch_channel.c:1104 New Channel sofia/publico/939165135 [bce7f5cc-f2e2-4ec6-9798-27a00b660b43] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_context]=[incoming] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_transfer_context]=[incoming] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_channel_name]=[line/CS2K] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_channel_type]=[line] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_line_name]=[CS2K] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [dtmf_type]=[rfc2833] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [rtp_info_when_no_2833]=[false] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [rtp_liberal_dtmf]=[true] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [refuse_t38]=[true] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [t38_passthru]=[false] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [absolute_codec_string]=[PCMA,PCMU] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [codec_string]=[PCMA,PCMU] 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5026 (sofia/publico/939165135) State Change CS_NEW -> CS_INIT 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_INIT (Cur 1 Tot 15351) 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:627 (sofia/publico/939165135) State INIT 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:93 sofia/publico/939165135 SOFIA INIT 2017-11-24 18:29:32.325313 [DEBUG] switch_core_port_allocator.c:183 UDP port robustness check for port 10822 pass 2017-11-24 18:29:32.325313 [DEBUG] sofia_glue.c:1298 sofia/publico/939165135 sending invite version: 1.9.0 git 4c78733 2017-05-16 19:50:21Z 64bit Local SDP: v=0 o=FreeSWITCH 1511533750 1511533751 IN IP4 100.10.10.10 s=FreeSWITCH c=IN IP4 100.10.10.10 t=0 0 m=audio 10822 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:40 sofia/publico/939165135 Standard INIT 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:48 (sofia/publico/939165135) State Change CS_INIT -> CS_ROUTING 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:627 (sofia/publico/939165135) State INIT going to sleep 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_ROUTING (Cur 1 Tot 15351) 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:643 (sofia/publico/939165135) State ROUTING 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:154 sofia/publico/939165135 SOFIA ROUTING 2017-11-24 18:29:32.325313 [DEBUG] switch_ivr_originate.c:67 (sofia/publico/939165135) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:643 (sofia/publico/939165135) State ROUTING going to sleep 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 15351) 2017-11-24 18:29:32.325313 [DEBUG] sofia.c:7249 Channel sofia/publico/939165135 entering state [calling][0] 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:662 (sofia/publico/939165135) State CONSUME_MEDIA 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:662 (sofia/publico/939165135) State CONSUME_MEDIA going to sleep 2017-11-24 18:29:34.205294 [DEBUG] sofia.c:7249 Channel sofia/publico/939165135 entering state [proceeding][183] 2017-11-24 18:29:34.205294 [DEBUG] sofia.c:7259 Remote SDP: v=0 o=genband 294525952 1511544573 IN IP4 100.10.100.10 s=- c=IN IP4 100.10.100.10 t=0 0 m=audio 41814 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=silenceSupp:off - - - - a=ptime:20 a=maxptime:30 a=sqn: 0 a=cdsc:1 image udptl t38 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5026 Set telephone-event payload to 101@8000 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:3425 Set Codec sofia/publico/939165135 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2017-11-24 18:29:34.205294 [DEBUG] switch_core_codec.c:111 sofia/publico/939165135 Original read codec set to PCMA:8 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5369 Set telephone-event payload to 101@8000 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5427 sofia/publico/939165135 Set 2833 dtmf send payload to 101 recv payload to 101 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/publico/939165135] 100.10.10.10 port 10822 -> 100.10.100.10 port 41814 codec: 8 ms: 20 2017-11-24 18:29:34.205294 [DEBUG] switch_rtp.c:4107 Starting timer [soft] 160 bytes per 20ms 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:8447 sofia/publico/939165135 Set 2833 dtmf send payload to 101 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:8454 sofia/publico/939165135 Set 2833 dtmf receive payload to 101 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:8477 sofia/publico/939165135 Set rtp dtmf delay to 40 2017-11-24 18:29:34.205294 [NOTICE] sofia_media.c:92 Pre-Answer sofia/publico/939165135! 2017-11-24 18:29:34.205294 [DEBUG] switch_channel.c:3490 (sofia/publico/939165135) Callstate Change DOWN -> EARLY 2017-11-24 18:29:34.205294 [DEBUG] switch_ivr_originate.c:3695 Originate Resulted in Success: [sofia/publico/939165135] 2017-11-24 18:29:34.205294 [INFO] switch_channel.c:3139 sofia/publico/939165135 Flipping CID from "" <0000000000> to "Outbound Call" <939165135> 2017-11-24 18:29:34.205294 [DEBUG] mod_commands.c:4865 (sofia/publico/939165135) State Change CS_CONSUME_MEDIA -> CS_EXECUTE 2017-11-24 18:29:34.205294 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_EXECUTE (Cur 1 Tot 15351) 2017-11-24 18:29:34.205294 [DEBUG] switch_core_state_machine.c:650 (sofia/publico/939165135) State EXECUTE 2017-11-24 18:29:34.205294 [DEBUG] mod_sofia.c:209 sofia/publico/939165135 SOFIA EXECUTE 2017-11-24 18:29:34.205294 [DEBUG] switch_core_state_machine.c:328 sofia/publico/939165135 Standard EXECUTE 2017-11-24 18:29:34.205294 [DEBUG] switch_core_session.c:2806 EXECUTE sofia/publico/939165135 txfax(/root/txfax.tiff) 2017-11-24 18:29:34.205294 [DEBUG] mod_spandsp_fax.c:1459 Raw read codec activation Success L16 20000 2017-11-24 18:29:34.205294 [DEBUG] switch_core_codec.c:223 sofia/publico/939165135 Push codec L16:100 2017-11-24 18:29:34.205294 [DEBUG] mod_spandsp_fax.c:1477 Raw write codec activation Success L16 2017-11-24 18:29:34.265321 [DEBUG] switch_rtp.c:7266 Correct audio ip/port confirmed. 2017-11-24 18:29:34.645315 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:36.185314 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:39.165314 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:40.685313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:41.265295 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:41.265295 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:41.265295 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:41.285310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:41.505307 [DEBUG] sofia.c:7249 Channel sofia/publico/939165135 entering state [completing][200] 2017-11-24 18:29:41.505307 [DEBUG] sofia.c:7256 Duplicate SDP v=0 o=genband 294525952 1511544573 IN IP4 100.10.100.10 s=- c=IN IP4 100.10.100.10 t=0 0 m=audio 41814 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=silenceSupp:off - - - - a=ptime:20 a=maxptime:30 a=sqn: 0 a=cdsc:1 image udptl t38 2017-11-24 18:29:41.525326 [DEBUG] sofia.c:7249 Channel sofia/publico/939165135 entering state [ready][200] 2017-11-24 18:29:41.525326 [NOTICE] sofia.c:8327 Channel [sofia/publico/939165135] has been answered 2017-11-24 18:29:41.525326 [DEBUG] switch_channel.c:3789 (sofia/publico/939165135) Callstate Change EARLY -> ACTIVE 2017-11-24 18:29:41.565310 [DEBUG] switch_rtp.c:7266 Correct audio ip/port confirmed. 2017-11-24 18:29:42.605320 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:43.785309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Abort (-8) in state T 2017-11-24 18:29:44.065316 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:44.085313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:44.085313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:44.085313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:44.105312 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:44.165313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:46.245310 [WARNING] sofia.c:6270 Ping succeeded euskaltel with code 200 - count 1/1/1, state UP 2017-11-24 18:29:46.625305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:47.085320 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:47.305315 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state T 2017-11-24 18:29:47.305315 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase A_CNG to B_RX 2017-11-24 18:29:47.305315 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-11-24 18:29:47.305315 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-11-24 18:29:47.325312 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:47.465303 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:47.885318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:47.965313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:48.165318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state T 2017-11-24 18:29:48.265308 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Bad HDLC CRC received 2017-11-24 18:29:48.265308 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Bad CRC and timer is 0 2017-11-24 18:29:48.365308 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:48.385310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:48.385310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:48.445320 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:48.465319 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 2017-11-24 18:29:55.345320 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 2017-11-24 18:29:55.605316 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state T 2017-11-24 18:29:57.025313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining) 2017-11-24 18:29:57.025313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: CSI without final frame tag 2017-11-24 18:29:57.025313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 03 40 35 36 31 39 33 39 31 35 39 20 20 20 20 20 20 20 20 20 20 20 2017-11-24 18:29:57.025313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Remote gave CSI as: "939165135" 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining) 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: DIS with final frame tag 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 13 80 00 4e 9a c4 80 d9 80 80 80 80 00 00 00 00 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state T 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase B_TX 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS: 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= 3G mobile network: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= V.8 capabilities: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Preferred octets: 256 octets 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= Can receive fax: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..00 11..= Supported data signalling rates: V.27 ter and V.29 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= 2-D coding: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1% 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 10..= Recording length: Unlimited 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .001 ....= Receiver's minimum scan line time: 5ms at 3.85 l/mm; T7.7 = T3.85 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= T.6 coding: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= "Field not valid" supported: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Multiple selective polling: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Polled sub-address: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= T.43 coding: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Plane interleave: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...1= R8x15.4lines/mm: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= Inch-based resolution preferred: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...1 ....= Metric-based resolution preferred: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= Selective polling: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Sub-addressing: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Password: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transmit a data file (polling): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transfer a character or mixed mode document (polling): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Character mode: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Digital network capability: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Duplex capability: Half only 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= JPEG coding: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Full colour mode: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= 12bits/pel component: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= No subsampling (1:1:1): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Custom illuminant: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Custom gamut range: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= North American Letter (215.9mm x 279.4mm): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= North American Legal (215.9mm x 355.6mm): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= HKM key management: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= RSA key management: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Override: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= HFX40 cipher: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Alternative cipher number 2: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Alternative cipher number 3: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= HFX40-I hashing: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= Extension indicator: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:317 === Negotiation Result ======================================================= 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:318 Remote station id: 939165135 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:319 Local station id: 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:320 Transfer Rate: 9600 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:322 ECM status on 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:323 remote country: 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:324 remote vendor: 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:325 remote model: 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:327 ============================================================================== 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Trying to send file '/root/txfax.tiff' 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start sending document 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Choose image type bi-level (0), compression T.6 (8) 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Minimum bits per row will be 0 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Starting page 1 of transfer 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Partial document buffer contains 25 frames (256 per frame) 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image width is A4 at 8040dpm x 3850dpm 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Put document with modem (6) V.29 at 9600bps 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state T to D 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DCS: 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= 3G mobile network: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= Receive fax: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..00 01..= Selected data signalling rate: V.29, 9600bps 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= 2-D coding: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..00= Recording width: 215mm +- 1% 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 10..= Recording length: Unlimited 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .111 ....= Minimum scan line time: 0ms 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Frame size: 256 octets 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= T.6 coding: Set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= Extension indicator: Not set 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: DCS with final frame tag 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 83 00 06 f8 44 2017-11-24 18:29:57.605294 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state D 2017-11-24 18:29:57.605294 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to B_TX 2017-11-24 18:29:57.605294 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-11-24 18:29:57.605294 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-11-24 18:29:58.765307 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state D 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state D 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D to D_TCF 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_TX to C_NON_ECM_TX 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 6 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase C_NON_ECM_TX, state D_TCF 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase C_NON_ECM_TX to B_RX 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D_TCF to D_POST_TCF 2017-11-24 18:30:04.025321 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state D_POST_TCF 2017-11-24 18:30:04.065319 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Abort (-8) in state D_POST_TCF 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Retry number 1 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase B_TX 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D_POST_TCF to D 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DCS: 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= 3G mobile network: Not set 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= Receive fax: Set 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..00 01..= Selected data signalling rate: V.29, 9600bps 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= 2-D coding: Not set 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..00= Recording width: 215mm +- 1% 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 10..= Recording length: Unlimited 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .111 ....= Minimum scan line time: 0ms 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Frame size: 256 octets 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= T.6 coding: Set 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= Extension indicator: Not set 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: DCS with final frame tag 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 83 00 06 f8 44 2017-11-24 18:30:04.285294 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state D 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining) 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: CFR with final frame tag 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 13 84 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state D 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Unexpected CFR frame in state D 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Status changing to 'Unexpected message received' 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Flushing queued phase B_TX 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_TX 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D to C 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: DCN with final frame tag 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 fb 2017-11-24 18:30:05.645293 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Abort (-8) in state C 2017-11-24 18:30:05.665314 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state C 2017-11-24 18:30:05.665314 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to D_TX 2017-11-24 18:30:05.665314 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-11-24 18:30:05.665314 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-11-24 18:30:06.725308 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state C 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state C 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Starting final pause before disconnecting 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_TX to E 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 1 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state C to B 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase E, state B 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:496 ============================================================================== 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:508 Fax processing not successful - result (13) Unexpected message received. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:513 Remote station id: 939165135 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:514 Local station id: 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:515 Pages transferred: 0 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:517 Total fax pages: 1 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:518 Image resolution: 8040x3850 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:519 Transfer Rate: 9600 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:521 ECM status on 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:522 remote country: 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:523 remote vendor: 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:524 remote model: 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:526 ============================================================================== 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state B to CALL_FINISHED 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase E to CALL_FINISHED 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 9 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX FAX exchange complete 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 9 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX FAX exchange complete 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Call completed 2017-11-24 18:30:07.825300 [DEBUG] switch_core_codec.c:248 sofia/publico/939165135 Restore previous codec PCMA:8. 2017-11-24 18:30:07.825300 [NOTICE] switch_core_state_machine.c:385 sofia/publico/939165135 has executed the last dialplan instruction, hanging up. 2017-11-24 18:30:07.825300 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/publico/939165135 [CS_EXECUTE] [NORMAL_CLEARING] 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:650 (sofia/publico/939165135) State EXECUTE going to sleep 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_HANGUP (Cur 1 Tot 15351) 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:850 (sofia/publico/939165135) Callstate Change ACTIVE -> HANGUP 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:852 (sofia/publico/939165135) State HANGUP 2017-11-24 18:30:07.825300 [DEBUG] mod_sofia.c:449 Channel sofia/publico/939165135 hanging up, cause: NORMAL_CLEARING 2017-11-24 18:30:07.825300 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/publico/939165135 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:60 sofia/publico/939165135 Standard HANGUP, cause: NORMAL_CLEARING 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:852 (sofia/publico/939165135) State HANGUP going to sleep 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:619 (sofia/publico/939165135) State Change CS_HANGUP -> CS_REPORTING 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_REPORTING (Cur 1 Tot 15351) 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:938 (sofia/publico/939165135) State REPORTING 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:174 sofia/publico/939165135 Standard REPORTING, cause: NORMAL_CLEARING 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:938 (sofia/publico/939165135) State REPORTING going to sleep 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:610 (sofia/publico/939165135) State Change CS_REPORTING -> CS_DESTROY 2017-11-24 18:30:07.825300 [DEBUG] switch_core_session.c:1712 Session 15351 (sofia/publico/939165135) Locked, Waiting on external entities 2017-11-24 18:30:07.825300 [NOTICE] switch_core_session.c:1730 Session 15351 (sofia/publico/939165135) Ended 2017-11-24 18:30:07.825300 [NOTICE] switch_core_session.c:1734 Close Channel sofia/publico/939165135 [CS_DESTROY] 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:741 (sofia/publico/939165135) Running State Change CS_DESTROY (Cur 0 Tot 15351) 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:751 (sofia/publico/939165135) State DESTROY 2017-11-24 18:30:07.825300 [DEBUG] mod_sofia.c:354 sofia/publico/939165135 SOFIA DESTROY 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:181 sofia/publico/939165135 Standard DESTROY 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:751 (sofia/publico/939165135) State DESTROY going to sleep