2017-02-28 19:49:20.617107 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/+18024488966@sip.nexmo.com [a2575d08-a1af-45da-b18f-a25da500da55] 2017-02-28 19:49:20.617107 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+18024488966@sip.nexmo.com) Running State Change CS_NEW (Cur 1 Tot 100) 2017-02-28 19:49:20.617107 [DEBUG] sofia.c:9815 sofia/internal/+18024488966@sip.nexmo.com receiving invite from 173.193.199.24:5060 version: 1.6.14 git a8d53fd 2017-01-12 17:48:02Z 32bit 2017-02-28 19:49:20.617107 [DEBUG] sofia.c:9927 IP 173.193.199.24 Approved by acl "nexmo[]". Access Granted. 2017-02-28 19:49:20.637083 [DEBUG] sofia.c:7041 Channel sofia/internal/+18024488966@sip.nexmo.com entering state [received][100] 2017-02-28 19:49:20.637083 [DEBUG] sofia.c:7051 Remote SDP: v=0 o=Nexmo 967708594 967708594 IN IP4 169.54.104.168 s=Nexmo c=IN IP4 169.54.104.168 t=0 0 m=audio 14214 RTP/AVP 8 0 97 18 9 117 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:9 G722/8000 a=rtpmap:117 speex/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 2017-02-28 19:49:20.637083 [DEBUG] sofia.c:7429 (sofia/internal/+18024488966@sip.nexmo.com) State Change CS_NEW -> CS_INIT 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/+18024488966@sip.nexmo.com) State NEW 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+18024488966@sip.nexmo.com) Running State Change CS_INIT (Cur 1 Tot 100) 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/+18024488966@sip.nexmo.com) State INIT 2017-02-28 19:49:20.637083 [DEBUG] mod_sofia.c:90 sofia/internal/+18024488966@sip.nexmo.com SOFIA INIT 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:40 sofia/internal/+18024488966@sip.nexmo.com Standard INIT 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/+18024488966@sip.nexmo.com) State Change CS_INIT -> CS_ROUTING 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/+18024488966@sip.nexmo.com) State INIT going to sleep 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+18024488966@sip.nexmo.com) Running State Change CS_ROUTING (Cur 1 Tot 100) 2017-02-28 19:49:20.637083 [DEBUG] switch_channel.c:2249 (sofia/internal/+18024488966@sip.nexmo.com) Callstate Change DOWN -> RINGING 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/+18024488966@sip.nexmo.com) State ROUTING 2017-02-28 19:49:20.637083 [DEBUG] mod_sofia.c:143 sofia/internal/+18024488966@sip.nexmo.com SOFIA ROUTING 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:236 sofia/internal/+18024488966@sip.nexmo.com Standard ROUTING 2017-02-28 19:49:20.637083 [INFO] mod_dialplan_xml.c:637 Processing +18024488966 <+18024488966>->1000 in context public Dialplan: sofia/internal/+18024488966@sip.nexmo.com parsing [public->unloop] continue=false Dialplan: sofia/internal/+18024488966@sip.nexmo.com Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/+18024488966@sip.nexmo.com Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/+18024488966@sip.nexmo.com parsing [public->outside_call] continue=true Dialplan: sofia/internal/+18024488966@sip.nexmo.com Absolute Condition [outside_call] Dialplan: sofia/internal/+18024488966@sip.nexmo.com Action set(outside_call=true) Dialplan: sofia/internal/+18024488966@sip.nexmo.com Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/+18024488966@sip.nexmo.com parsing [public->call_debug] continue=true Dialplan: sofia/internal/+18024488966@sip.nexmo.com Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/+18024488966@sip.nexmo.com parsing [public->nexmo_1000] continue=false Dialplan: sofia/internal/+18024488966@sip.nexmo.com Regex (PASS) [nexmo_1000] destination_number(1000) =~ /^1000$/ break=on-false Dialplan: sofia/internal/+18024488966@sip.nexmo.com Action info() Dialplan: sofia/internal/+18024488966@sip.nexmo.com Action answer() Dialplan: sofia/internal/+18024488966@sip.nexmo.com Action playback(silence_stream://2000) Dialplan: sofia/internal/+18024488966@sip.nexmo.com Action rxfax(/tmp/FAX-${uuid}.tif) Dialplan: sofia/internal/+18024488966@sip.nexmo.com Action hangup() 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/+18024488966@sip.nexmo.com) State Change CS_ROUTING -> CS_EXECUTE 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/+18024488966@sip.nexmo.com) State ROUTING going to sleep 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+18024488966@sip.nexmo.com) Running State Change CS_EXECUTE (Cur 1 Tot 100) 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/+18024488966@sip.nexmo.com) State EXECUTE 2017-02-28 19:49:20.637083 [DEBUG] mod_sofia.c:198 sofia/internal/+18024488966@sip.nexmo.com SOFIA EXECUTE 2017-02-28 19:49:20.637083 [DEBUG] switch_core_state_machine.c:328 sofia/internal/+18024488966@sip.nexmo.com Standard EXECUTE EXECUTE sofia/internal/+18024488966@sip.nexmo.com set(outside_call=true) 2017-02-28 19:49:20.637083 [DEBUG] mod_dptools.c:1527 SET sofia/internal/+18024488966@sip.nexmo.com [outside_call]=[true] EXECUTE sofia/internal/+18024488966@sip.nexmo.com export(RFC2822_DATE=Tue, 28 Feb 2017 19:49:20 +0000) 2017-02-28 19:49:20.637083 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 28 Feb 2017 19:49:20 +0000] EXECUTE sofia/internal/+18024488966@sip.nexmo.com answer() 2017-02-28 19:49:20.637083 [DEBUG] mod_sofia.c:817 Disabling proxy mode due to call answer with no bridge 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4433 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4433 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [iLBC:97:8000:20:0:1]/[opus:116:48000:20:0:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [iLBC:97:8000:20:0:1]/[G722:9:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4433 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [speex:117:16000:20:0:1]/[opus:116:48000:20:0:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [speex:117:16000:20:0:1]/[G722:9:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [speex:117:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [speex:117:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4294 Set telephone-event payload to 101@8000 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:3043 Set Codec sofia/internal/+18024488966@sip.nexmo.com PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2017-02-28 19:49:20.637083 [DEBUG] switch_core_codec.c:111 sofia/internal/+18024488966@sip.nexmo.com Original read codec set to PCMA:8 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4637 Set telephone-event payload to 101@8000 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:4696 sofia/internal/+18024488966@sip.nexmo.com Set 2833 dtmf send payload to 101 recv payload to 101 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:6703 AUDIO RTP [sofia/internal/+18024488966@sip.nexmo.com] 138.197.209.147 port 25048 -> 169.54.104.168 port 14214 codec: 8 ms: 20 2017-02-28 19:49:20.637083 [DEBUG] switch_rtp.c:3878 Starting timer [soft] 160 bytes per 20ms 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:7009 sofia/internal/+18024488966@sip.nexmo.com Set 2833 dtmf send payload to 101 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:7016 sofia/internal/+18024488966@sip.nexmo.com Set 2833 dtmf receive payload to 101 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:7039 sofia/internal/+18024488966@sip.nexmo.com Set rtp dtmf delay to 40 2017-02-28 19:49:20.637083 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/+18024488966@sip.nexmo.com! 2017-02-28 19:49:20.637083 [DEBUG] switch_channel.c:3473 (sofia/internal/+18024488966@sip.nexmo.com) Callstate Change RINGING -> EARLY 2017-02-28 19:49:20.637083 [DEBUG] switch_core_media.c:6686 Audio params are unchanged for sofia/internal/+18024488966@sip.nexmo.com. 2017-02-28 19:49:20.637083 [DEBUG] mod_sofia.c:849 Local SDP sofia/internal/+18024488966@sip.nexmo.com: v=0 o=FreeSWITCH 1488286312 1488286313 IN IP4 138.197.209.147 s=FreeSWITCH c=IN IP4 138.197.209.147 t=0 0 m=audio 25048 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-02-28 19:49:20.637083 [DEBUG] sofia.c:7041 Channel sofia/internal/+18024488966@sip.nexmo.com entering state [completed][200] 2017-02-28 19:49:20.637083 [NOTICE] mod_dptools.c:1309 Channel [sofia/internal/+18024488966@sip.nexmo.com] has been answered 2017-02-28 19:49:20.637083 [DEBUG] switch_channel.c:3772 (sofia/internal/+18024488966@sip.nexmo.com) Callstate Change EARLY -> ACTIVE EXECUTE sofia/internal/+18024488966@sip.nexmo.com playback(silence_stream://2000) 2017-02-28 19:49:20.637083 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-02-28 19:49:20.737114 [DEBUG] sofia.c:7041 Channel sofia/internal/+18024488966@sip.nexmo.com entering state [ready][200] 2017-02-28 19:49:21.117142 [DEBUG] switch_rtp.c:6994 Correct audio ip/port confirmed. 2017-02-28 19:49:22.637084 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://2000 EXECUTE sofia/internal/+18024488966@sip.nexmo.com rxfax(/tmp/FAX-a2575d08-a1af-45da-b18f-a25da500da55.tif) 2017-02-28 19:49:22.637084 [DEBUG] mod_spandsp_fax.c:1446 Raw read codec activation Success L16 20000 2017-02-28 19:49:22.637084 [DEBUG] switch_core_codec.c:223 sofia/internal/+18024488966@sip.nexmo.com Push codec L16:100 2017-02-28 19:49:22.637084 [DEBUG] mod_spandsp_fax.c:1464 Raw write codec activation Success L16 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase A_CED, state ANSWERING 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Starting answer mode 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase A_CED to B_TX 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state ANSWERING to R 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Sending ident 'SpanDSP Fax Ident' 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: CSI without final frame tag 2017-02-28 19:49:25.717083 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 03 40 74 6e 65 64 49 20 78 61 46 20 50 53 44 6e 61 70 53 20 20 20 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state R 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS: 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= 3G mobile network: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= V.8 capabilities: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Preferred octets: 256 octets 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= Can receive fax: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= 2-D coding: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1% 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 10..= Recording length: Unlimited 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= T.6 coding: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= "Field not valid" supported: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Multiple selective polling: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Polled sub-address: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= T.43 coding: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Plane interleave: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...1= R8x15.4lines/mm: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= Inch-based resolution preferred: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...1 ....= Metric-based resolution preferred: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Selective polling: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Sub-addressing: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Password: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transmit a data file (polling): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transfer a character or mixed mode document (polling): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Character mode: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Digital network capability: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Duplex capability: Half only 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= JPEG coding: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Full colour mode: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= 12bits/pel component: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= No subsampling (1:1:1): Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Custom illuminant: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Custom gamut range: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= North American Letter (215.9mm x 279.4mm): Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...1 ....= North American Legal (215.9mm x 355.6mm): Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..1. ....= Single-progression sequential coding (Rec. T.85) basic: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= Extension indicator: Not set 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: DIS with final frame tag 2017-02-28 19:49:27.297146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 80 00 ee fa c4 80 9d 80 80 80 78 2017-02-28 19:49:27.757088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state R 2017-02-28 19:49:27.837087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state R 2017-02-28 19:49:27.837087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_TX to B_RX 2017-02-28 19:49:27.837087 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-02-28 19:49:27.837087 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:49:27.837087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4 2017-02-28 19:49:28.617105 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state R 2017-02-28 19:49:28.817107 [DEBUG] sofia.c:7041 Channel sofia/internal/+18024488966@sip.nexmo.com entering state [received][100] 2017-02-28 19:49:28.817107 [DEBUG] sofia.c:7051 Remote SDP: v=0 o=Nexmo 967708594 967708595 IN IP4 169.54.104.168 s=Nexmo c=IN IP4 169.54.104.168 t=0 0 m=image 4557 udptl t38 c=IN IP4 169.54.104.168 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxDatagram:89 a=T38FaxUdpEC:t38UDPFEC 2017-02-28 19:49:28.817107 [DEBUG] switch_core_media.c:3950 sofia/internal/+18024488966@sip.nexmo.com T38 REFUSE on request 2017-02-28 19:49:28.817107 [DEBUG] sofia.c:7946 Reinvite resulted in codec negotiation failure. 2017-02-28 19:49:28.817107 [DEBUG] sofia.c:7034 Channel sofia/internal/+18024488966@sip.nexmo.com skipping state [ready][488] 2017-02-28 19:49:28.877132 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state R 2017-02-28 19:49:28.877132 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4-flagged 2017-02-28 19:49:28.917097 [DEBUG] sofia.c:7041 Channel sofia/internal/+18024488966@sip.nexmo.com entering state [received][100] 2017-02-28 19:49:28.917097 [DEBUG] sofia.c:7051 Remote SDP: v=0 o=Nexmo 967708594 967708596 IN IP4 169.54.104.168 s=Nexmo c=IN IP4 169.54.104.168 t=0 0 m=audio 14214 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 2017-02-28 19:49:28.917097 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-02-28 19:49:28.917097 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-02-28 19:49:28.917097 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-02-28 19:49:28.917097 [DEBUG] switch_core_media.c:4378 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-02-28 19:49:28.917097 [DEBUG] switch_core_media.c:4433 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-02-28 19:49:28.917097 [DEBUG] switch_core_media.c:4294 Set telephone-event payload to 101@8000 2017-02-28 19:49:28.917097 [DEBUG] switch_core_media.c:4637 Set telephone-event payload to 101@8000 2017-02-28 19:49:28.917097 [DEBUG] switch_core_media.c:4696 sofia/internal/+18024488966@sip.nexmo.com Set 2833 dtmf send payload to 101 recv payload to 101 2017-02-28 19:49:28.917097 [DEBUG] switch_core_media.c:6686 Audio params are unchanged for sofia/internal/+18024488966@sip.nexmo.com. 2017-02-28 19:49:28.917097 [DEBUG] sofia.c:7938 Processing updated SDP 2017-02-28 19:49:28.917097 [DEBUG] sofia.c:7041 Channel sofia/internal/+18024488966@sip.nexmo.com entering state [completed][200] 2017-02-28 19:49:28.997118 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Abort (-8) in state R 2017-02-28 19:49:28.997118 [DEBUG] sofia.c:7041 Channel sofia/internal/+18024488966@sip.nexmo.com entering state [ready][200] 2017-02-28 19:49:29.657104 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state R 2017-02-28 19:49:29.657104 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4-dropped 2017-02-28 19:49:29.837101 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 T4-dropped expired in phase B_RX, state R. The line is now quiet. 2017-02-28 19:49:29.837101 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Retry number 1 2017-02-28 19:49:29.837101 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to B_TX 2017-02-28 19:49:29.837101 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:49:29.837101 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-02-28 19:49:29.837101 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Sending ident 'SpanDSP Fax Ident' 2017-02-28 19:49:29.837101 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: CSI without final frame tag 2017-02-28 19:49:29.837101 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 03 40 74 6e 65 64 49 20 78 61 46 20 50 53 44 6e 61 70 53 20 20 20 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state R 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS: 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= 3G mobile network: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= V.8 capabilities: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Preferred octets: 256 octets 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= Can receive fax: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= 2-D coding: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1% 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 10..= Recording length: Unlimited 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= T.6 coding: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= "Field not valid" supported: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Multiple selective polling: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Polled sub-address: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= T.43 coding: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Plane interleave: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...1= R8x15.4lines/mm: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= Inch-based resolution preferred: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...1 ....= Metric-based resolution preferred: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Selective polling: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Sub-addressing: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Password: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transmit a data file (polling): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transfer a character or mixed mode document (polling): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Character mode: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Digital network capability: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Duplex capability: Half only 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= JPEG coding: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Full colour mode: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= 12bits/pel component: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= No subsampling (1:1:1): Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Custom illuminant: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Custom gamut range: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= North American Letter (215.9mm x 279.4mm): Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...1 ....= North American Legal (215.9mm x 355.6mm): Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..1. ....= Single-progression sequential coding (Rec. T.85) basic: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= Extension indicator: Not set 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: DIS with final frame tag 2017-02-28 19:49:31.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 80 00 ee fa c4 80 9d 80 80 80 78 2017-02-28 19:49:31.897087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state R 2017-02-28 19:49:31.977109 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state R 2017-02-28 19:49:31.977109 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_TX to B_RX 2017-02-28 19:49:31.977109 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-02-28 19:49:31.977109 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:49:31.977109 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4 2017-02-28 19:49:35.437088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Retry number 2 2017-02-28 19:49:35.437088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to B_TX 2017-02-28 19:49:35.437088 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:49:35.437088 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-02-28 19:49:35.437088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Sending ident 'SpanDSP Fax Ident' 2017-02-28 19:49:35.437088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: CSI without final frame tag 2017-02-28 19:49:35.437088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 03 40 74 6e 65 64 49 20 78 61 46 20 50 53 44 6e 61 70 53 20 20 20 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state R 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS: 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= 3G mobile network: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= V.8 capabilities: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Preferred octets: 256 octets 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= Can receive fax: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= 2-D coding: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1% 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 10..= Recording length: Unlimited 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= T.6 coding: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= "Field not valid" supported: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Multiple selective polling: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Polled sub-address: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= T.43 coding: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Plane interleave: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...1= R8x15.4lines/mm: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= Inch-based resolution preferred: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...1 ....= Metric-based resolution preferred: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Selective polling: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Sub-addressing: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Password: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transmit a data file (polling): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transfer a character or mixed mode document (polling): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Character mode: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Digital network capability: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Duplex capability: Half only 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= JPEG coding: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Full colour mode: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= 12bits/pel component: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= No subsampling (1:1:1): Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Custom illuminant: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Custom gamut range: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= North American Letter (215.9mm x 279.4mm): Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...1 ....= North American Legal (215.9mm x 355.6mm): Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..1. ....= Single-progression sequential coding (Rec. T.85) basic: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= Extension indicator: Not set 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: DIS with final frame tag 2017-02-28 19:49:37.017086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 80 00 ee fa c4 80 9d 80 80 80 78 2017-02-28 19:49:37.477085 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state R 2017-02-28 19:49:37.557099 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state R 2017-02-28 19:49:37.557099 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_TX to B_RX 2017-02-28 19:49:37.557099 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-02-28 19:49:37.557099 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:49:37.557099 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4 2017-02-28 19:49:38.957084 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state R 2017-02-28 19:49:39.197087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state R 2017-02-28 19:49:39.197087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4-flagged 2017-02-28 19:49:40.697084 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T4-flagged (12000 remaining) 2017-02-28 19:49:40.697084 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: TSI without final frame tag 2017-02-28 19:49:40.697084 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 03 43 20 20 20 20 20 20 20 20 20 20 33 33 36 36 35 35 36 30 35 36 2017-02-28 19:49:40.697084 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Remote gave TSI as: "6506556633 " 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining) 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: DCS with final frame tag 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 13 83 00 e2 f0 80 80 80 80 80 80 08 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state R 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DCS: 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= 3G mobile network: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= Receive fax: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..10 00..= Selected data signalling rate: V.17 14400bps 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= 2-D coding: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..00= Recording width: 215mm +- 1% 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 00..= Recording length: A4 (297mm) 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .111 ....= Minimum scan line time: 0ms 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Error correction mode (ECM): Non-ECM 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Frame size: 256 octets 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= T.6 coding: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= "Field not valid" supported: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= T.43 coding: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Plane interleave: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= R8x15.4lines/mm: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Resolution type selection: Metric 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Sub-addressing: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Sender identification transmission: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Character mode: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Digital network capability: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Duplex capability: Half only 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Full colour mode: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Full colour mode: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Preferred Huffman tables: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= 12bits/pel component: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= No subsampling (1:1:1): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Custom illuminant: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Custom gamut range: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= North American Letter (215.9mm x 279.4mm): Set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= North American Legal (215.9mm x 355.6mm): Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= Extension indicator: Not set 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Far end selected compression T.4 2-D (4) 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:317 === Negotiation Result ======================================================= 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:318 Remote station id: 6506556633 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:319 Local station id: SpanDSP Fax Ident 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:320 Transfer Rate: 14400 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:322 ECM status off 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:323 remote country: 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:324 remote vendor: 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:325 remote model: 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:327 ============================================================================== 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Get document with modem (7) V.17 at 14400bps 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state R to F_TCF 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase C_NON_ECM_RX 2017-02-28 19:49:41.117115 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:49:41.197106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state F_TCF 2017-02-28 19:49:41.197106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to C_NON_ECM_RX 2017-02-28 19:49:41.197106 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:49:41.197106 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 7 2017-02-28 19:49:41.197106 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:49:41.397103 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state F_TCF 2017-02-28 19:49:41.397103 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_TCF 2017-02-28 19:49:41.497118 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state F_TCF 2017-02-28 19:49:42.417100 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Abort (-8) in state F_TCF 2017-02-28 19:49:42.797110 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training succeeded (-4) in state F_TCF 2017-02-28 19:49:42.797110 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2 (42560 remaining) 2017-02-28 19:49:44.417106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state F_TCF 2017-02-28 19:49:44.417106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Trainability (TCF) test result - 23250 total bits. longest run of zeros was 21600 2017-02-28 19:49:44.417106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase C_NON_ECM_RX to B_TX 2017-02-28 19:49:44.417106 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:49:44.417106 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-02-28 19:49:44.417106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_TCF to F_CFR 2017-02-28 19:49:44.417106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: CFR with final frame tag 2017-02-28 19:49:44.417106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 84 2017-02-28 19:49:45.497103 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state F_CFR 2017-02-28 19:49:45.577092 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state F_CFR 2017-02-28 19:49:45.577092 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_CFR to F_DOC_NON_ECM 2017-02-28 19:49:45.577092 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_TX to C_NON_ECM_RX 2017-02-28 19:49:45.577092 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:49:45.577092 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 7 2017-02-28 19:49:45.577092 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:49:45.577092 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:49:45.597127 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state F_DOC_NON_ECM 2017-02-28 19:49:47.117114 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state F_DOC_NON_ECM 2017-02-28 19:49:47.117114 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_DOC_NON_ECM 2017-02-28 19:49:47.257097 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state F_DOC_NON_ECM 2017-02-28 19:49:47.277086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training succeeded (-4) in state F_DOC_NON_ECM 2017-02-28 19:49:47.277086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2 (42560 remaining) 2017-02-28 19:50:02.297084 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_DOC_NON_ECM to F_POST_DOC_NON_ECM 2017-02-28 19:50:02.297084 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_RX 2017-02-28 19:50:02.297084 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:50:02.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:02.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase C_NON_ECM_RX to D_RX 2017-02-28 19:50:02.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-02-28 19:50:02.417093 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:50:02.517089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:02.757100 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:02.757100 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2-flagged 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2-flagged (16640 remaining) 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: MPS with final frame tag 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 13 4f 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state F_POST_DOC_NON_ECM 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_TX 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Page no = 1 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image size = 1728 x 2156 pixels 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image resolution = 8040/m x 7700/m 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Compression = T.4 2-D (4) 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Compressed image size = 27032 bytes 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Bad rows = 0 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Longest bad row run = 0 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Page quality is perfect 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:428 ==== Page Received =========================================================== 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:429 Page no = 1 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:430 Image type = bi-level (bi-level in the file) 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:431 Image size = 1728 x 2156 pixels (1728 x 2156 pixels in the file) 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:432 Image resolution = 8040/m x 7700/m (8040/m x 7700/m in the file) 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:433 Compression = T.4 2-D (4) 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:434 Compressed image size = 27032 bytes 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:435 Bad rows = 0 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:436 Longest bad row run = 0 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:437 ============================================================================== 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_POST_DOC_NON_ECM to III_Q 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: MCF with final frame tag 2017-02-28 19:50:03.677113 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 8c 2017-02-28 19:50:03.757103 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state III_Q 2017-02-28 19:50:03.757103 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_RX to D_TX 2017-02-28 19:50:03.757103 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:50:03.757103 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-02-28 19:50:04.817087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state III_Q 2017-02-28 19:50:04.897088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state III_Q 2017-02-28 19:50:04.897088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state III_Q to F_DOC_NON_ECM 2017-02-28 19:50:04.897088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_TX to C_NON_ECM_RX 2017-02-28 19:50:04.897088 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:50:04.897088 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 7 2017-02-28 19:50:04.897088 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:50:04.897088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:50:06.437091 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state F_DOC_NON_ECM 2017-02-28 19:50:06.437091 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_DOC_NON_ECM 2017-02-28 19:50:06.577096 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state F_DOC_NON_ECM 2017-02-28 19:50:06.597093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training succeeded (-4) in state F_DOC_NON_ECM 2017-02-28 19:50:06.597093 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2 (42560 remaining) 2017-02-28 19:50:21.617085 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_DOC_NON_ECM to F_POST_DOC_NON_ECM 2017-02-28 19:50:21.617085 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_RX 2017-02-28 19:50:21.617085 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:50:21.737086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:21.737086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase C_NON_ECM_RX to D_RX 2017-02-28 19:50:21.737086 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-02-28 19:50:21.737086 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:50:21.837079 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:22.077146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:22.077146 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2-flagged 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2-flagged (16480 remaining) 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: MPS with final frame tag 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 13 4f 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state F_POST_DOC_NON_ECM 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_TX 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Page no = 2 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image size = 1728 x 2155 pixels 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image resolution = 8040/m x 7700/m 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Compression = T.4 2-D (4) 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Compressed image size = 26978 bytes 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Bad rows = 1 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Longest bad row run = 1 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Page quality is good 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:428 ==== Page Received =========================================================== 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:429 Page no = 2 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:430 Image type = bi-level (bi-level in the file) 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:431 Image size = 1728 x 2155 pixels (1728 x 2155 pixels in the file) 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:432 Image resolution = 8040/m x 7700/m (8040/m x 7700/m in the file) 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:433 Compression = T.4 2-D (4) 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:434 Compressed image size = 26978 bytes 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:435 Bad rows = 1 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:436 Longest bad row run = 1 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:437 ============================================================================== 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_POST_DOC_NON_ECM to III_Q 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: MCF with final frame tag 2017-02-28 19:50:23.017107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 8c 2017-02-28 19:50:23.077174 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state III_Q 2017-02-28 19:50:23.077174 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_RX to D_TX 2017-02-28 19:50:23.077174 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:50:23.077174 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-02-28 19:50:24.157107 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state III_Q 2017-02-28 19:50:24.237128 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state III_Q 2017-02-28 19:50:24.237128 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state III_Q to F_DOC_NON_ECM 2017-02-28 19:50:24.237128 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_TX to C_NON_ECM_RX 2017-02-28 19:50:24.237128 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:50:24.237128 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 7 2017-02-28 19:50:24.237128 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:50:24.237128 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:50:25.797106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state F_DOC_NON_ECM 2017-02-28 19:50:25.797106 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_DOC_NON_ECM 2017-02-28 19:50:25.937091 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state F_DOC_NON_ECM 2017-02-28 19:50:25.957085 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training succeeded (-4) in state F_DOC_NON_ECM 2017-02-28 19:50:25.957085 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2 (42400 remaining) 2017-02-28 19:50:39.557094 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_DOC_NON_ECM to F_POST_DOC_NON_ECM 2017-02-28 19:50:39.557094 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_RX 2017-02-28 19:50:39.557094 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:50:39.677110 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:39.677110 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase C_NON_ECM_RX to D_RX 2017-02-28 19:50:39.677110 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-02-28 19:50:39.677110 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:50:39.777125 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:40.017094 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:40.017094 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2-flagged 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2-flagged (16480 remaining) 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: MPS with final frame tag 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 13 4f 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state F_POST_DOC_NON_ECM 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_TX 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Page no = 3 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image size = 1728 x 2156 pixels 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image resolution = 8040/m x 7700/m 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Compression = T.4 2-D (4) 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Compressed image size = 24483 bytes 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Bad rows = 0 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Longest bad row run = 0 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Page quality is perfect 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:428 ==== Page Received =========================================================== 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:429 Page no = 3 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:430 Image type = bi-level (bi-level in the file) 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:431 Image size = 1728 x 2156 pixels (1728 x 2156 pixels in the file) 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:432 Image resolution = 8040/m x 7700/m (8040/m x 7700/m in the file) 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:433 Compression = T.4 2-D (4) 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:434 Compressed image size = 24483 bytes 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:435 Bad rows = 0 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:436 Longest bad row run = 0 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:437 ============================================================================== 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_POST_DOC_NON_ECM to III_Q 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: MCF with final frame tag 2017-02-28 19:50:40.957087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 8c 2017-02-28 19:50:41.037108 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state III_Q 2017-02-28 19:50:41.037108 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_RX to D_TX 2017-02-28 19:50:41.037108 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:50:41.037108 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-02-28 19:50:42.117130 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state III_Q 2017-02-28 19:50:42.197086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state III_Q 2017-02-28 19:50:42.197086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state III_Q to F_DOC_NON_ECM 2017-02-28 19:50:42.197086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_TX to C_NON_ECM_RX 2017-02-28 19:50:42.197086 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:50:42.197086 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 7 2017-02-28 19:50:42.197086 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:50:42.197086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:50:43.757086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state F_DOC_NON_ECM 2017-02-28 19:50:43.757086 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_DOC_NON_ECM 2017-02-28 19:50:43.897090 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state F_DOC_NON_ECM 2017-02-28 19:50:43.917095 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Training succeeded (-4) in state F_DOC_NON_ECM 2017-02-28 19:50:43.917095 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2 (42400 remaining) 2017-02-28 19:50:55.017085 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_DOC_NON_ECM to F_POST_DOC_NON_ECM 2017-02-28 19:50:55.017085 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_RX 2017-02-28 19:50:55.017085 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2 2017-02-28 19:50:55.137110 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:55.137110 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase C_NON_ECM_RX to D_RX 2017-02-28 19:50:55.137110 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-02-28 19:50:55.137110 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:50:55.237090 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:55.477099 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state F_POST_DOC_NON_ECM 2017-02-28 19:50:55.477099 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2-flagged 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2-flagged (16640 remaining) 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: EOP with final frame tag 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 13 2f 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state F_POST_DOC_NON_ECM 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 End of procedure detected 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_TX 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Page no = 4 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image size = 1728 x 2156 pixels 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image resolution = 8040/m x 7700/m 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Compression = T.4 2-D (4) 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Compressed image size = 19971 bytes 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Bad rows = 0 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Longest bad row run = 0 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Page quality is perfect 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:428 ==== Page Received =========================================================== 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:429 Page no = 4 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:430 Image type = bi-level (bi-level in the file) 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:431 Image size = 1728 x 2156 pixels (1728 x 2156 pixels in the file) 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:432 Image resolution = 8040/m x 7700/m (8040/m x 7700/m in the file) 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:433 Compression = T.4 2-D (4) 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:434 Compressed image size = 19971 bytes 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:435 Bad rows = 0 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:436 Longest bad row run = 0 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:437 ============================================================================== 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state F_POST_DOC_NON_ECM to III_Q 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: MCF with final frame tag 2017-02-28 19:50:56.397089 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 8c 2017-02-28 19:50:56.477094 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state III_Q 2017-02-28 19:50:56.477094 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_RX to D_TX 2017-02-28 19:50:56.477094 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0 2017-02-28 19:50:56.477094 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4 2017-02-28 19:50:56.917116 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/‘hi'or‘x’='x'@138.197.209.147 [f4cc431e-c613-4cf3-af55-975643381f0f] 2017-02-28 19:50:56.917116 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) Running State Change CS_NEW (Cur 2 Tot 101) 2017-02-28 19:50:56.917116 [DEBUG] sofia.c:9815 sofia/internal/‘hi'or‘x’='x'@138.197.209.147 receiving invite from 62.210.245.31:41254 version: 1.6.14 git a8d53fd 2017-01-12 17:48:02Z 32bit 2017-02-28 19:50:56.917116 [DEBUG] sofia.c:9982 IP 62.210.245.31 Rejected by acl "nexmo". Falling back to Digest auth. 2017-02-28 19:50:56.917116 [DEBUG] sofia.c:2333 detaching session f4cc431e-c613-4cf3-af55-975643381f0f 2017-02-28 19:50:56.917116 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) State NEW 2017-02-28 19:50:57.537088 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state III_Q 2017-02-28 19:50:57.617091 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state III_Q 2017-02-28 19:50:57.617091 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_TX to D_RX 2017-02-28 19:50:57.617091 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 2017-02-28 19:50:57.617091 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 2017-02-28 19:50:57.617091 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4 2017-02-28 19:50:59.037083 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state III_Q 2017-02-28 19:50:59.277098 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state III_Q 2017-02-28 19:50:59.277098 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4-flagged 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T4-flagged (16320 remaining) 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: DCN with final frame tag 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 13 fb 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state III_Q 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:496 ============================================================================== 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:502 Fax successfully received. 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:513 Remote station id: 6506556633 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:514 Local station id: SpanDSP Fax Ident 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:515 Pages transferred: 4 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:517 Total fax pages: 4 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:518 Image resolution: 8040x7700 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:519 Transfer Rate: 14400 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:521 ECM status off 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:522 remote country: 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:523 remote vendor: 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:524 remote model: 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:526 ============================================================================== 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state III_Q to CALL_FINISHED 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_RX to CALL_FINISHED 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 9 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX FAX exchange complete 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 9 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX FAX exchange complete 2017-02-28 19:51:00.237108 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Call completed 2017-02-28 19:51:00.257108 [DEBUG] switch_core_codec.c:248 sofia/internal/+18024488966@sip.nexmo.com Restore previous codec PCMA:8. EXECUTE sofia/internal/+18024488966@sip.nexmo.com hangup() 2017-02-28 19:51:00.257108 [NOTICE] mod_dptools.c:1283 Hangup sofia/internal/+18024488966@sip.nexmo.com [CS_EXECUTE] [NORMAL_CLEARING] 2017-02-28 19:51:00.257108 [DEBUG] switch_core_session.c:2797 sofia/internal/+18024488966@sip.nexmo.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/+18024488966@sip.nexmo.com) State EXECUTE going to sleep 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+18024488966@sip.nexmo.com) Running State Change CS_HANGUP (Cur 2 Tot 101) 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/+18024488966@sip.nexmo.com) Callstate Change ACTIVE -> HANGUP 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/+18024488966@sip.nexmo.com) State HANGUP 2017-02-28 19:51:00.257108 [DEBUG] mod_sofia.c:438 Channel sofia/internal/+18024488966@sip.nexmo.com hanging up, cause: NORMAL_CLEARING 2017-02-28 19:51:00.257108 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/+18024488966@sip.nexmo.com 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:60 sofia/internal/+18024488966@sip.nexmo.com Standard HANGUP, cause: NORMAL_CLEARING 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/+18024488966@sip.nexmo.com) State HANGUP going to sleep 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/+18024488966@sip.nexmo.com) State Change CS_HANGUP -> CS_REPORTING 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+18024488966@sip.nexmo.com) Running State Change CS_REPORTING (Cur 2 Tot 101) 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/+18024488966@sip.nexmo.com) State REPORTING 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:174 sofia/internal/+18024488966@sip.nexmo.com Standard REPORTING, cause: NORMAL_CLEARING 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/+18024488966@sip.nexmo.com) State REPORTING going to sleep 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/+18024488966@sip.nexmo.com) State Change CS_REPORTING -> CS_DESTROY 2017-02-28 19:51:00.257108 [DEBUG] switch_core_session.c:1647 Session 100 (sofia/internal/+18024488966@sip.nexmo.com) Locked, Waiting on external entities 2017-02-28 19:51:00.257108 [NOTICE] switch_core_session.c:1665 Session 100 (sofia/internal/+18024488966@sip.nexmo.com) Ended 2017-02-28 19:51:00.257108 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/+18024488966@sip.nexmo.com [CS_DESTROY] 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/+18024488966@sip.nexmo.com) Running State Change CS_DESTROY (Cur 1 Tot 101) 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/+18024488966@sip.nexmo.com) State DESTROY 2017-02-28 19:51:00.257108 [DEBUG] mod_sofia.c:343 sofia/internal/+18024488966@sip.nexmo.com SOFIA DESTROY 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:181 sofia/internal/+18024488966@sip.nexmo.com Standard DESTROY 2017-02-28 19:51:00.257108 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/+18024488966@sip.nexmo.com) State DESTROY going to sleep 2017-02-28 19:51:06.957127 [WARNING] switch_core_state_machine.c:687 f4cc431e-c613-4cf3-af55-975643381f0f sofia/internal/‘hi'or‘x’='x'@138.197.209.147 Abandoned 2017-02-28 19:51:06.957127 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/internal/‘hi'or‘x’='x'@138.197.209.147 [CS_NEW] [WRONG_CALL_STATE] 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) Running State Change CS_HANGUP (Cur 1 Tot 101) 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) Callstate Change DOWN -> HANGUP 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) State HANGUP 2017-02-28 19:51:06.957127 [DEBUG] mod_sofia.c:438 Channel sofia/internal/‘hi'or‘x’='x'@138.197.209.147 hanging up, cause: WRONG_CALL_STATE 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:60 sofia/internal/‘hi'or‘x’='x'@138.197.209.147 Standard HANGUP, cause: WRONG_CALL_STATE 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) State HANGUP going to sleep 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) State Change CS_HANGUP -> CS_REPORTING 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) Running State Change CS_REPORTING (Cur 1 Tot 101) 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) State REPORTING 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:174 sofia/internal/‘hi'or‘x’='x'@138.197.209.147 Standard REPORTING, cause: WRONG_CALL_STATE 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) State REPORTING going to sleep 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) State Change CS_REPORTING -> CS_DESTROY 2017-02-28 19:51:06.957127 [DEBUG] switch_core_session.c:1647 Session 101 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) Locked, Waiting on external entities 2017-02-28 19:51:06.957127 [NOTICE] switch_core_session.c:1665 Session 101 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) Ended 2017-02-28 19:51:06.957127 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/‘hi'or‘x’='x'@138.197.209.147 [CS_DESTROY] 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) Running State Change CS_DESTROY (Cur 0 Tot 101) 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) State DESTROY 2017-02-28 19:51:06.957127 [DEBUG] mod_sofia.c:343 sofia/internal/‘hi'or‘x’='x'@138.197.209.147 SOFIA DESTROY 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:181 sofia/internal/‘hi'or‘x’='x'@138.197.209.147 Standard DESTROY 2017-02-28 19:51:06.957127 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/‘hi'or‘x’='x'@138.197.209.147) State DESTROY going to sleep