span style="color: cornflowerblue; font-weight: bold;"> 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