[Freeswitch-users] mod_fax not working

Mathieu Parent math.parent at gmail.com
Fri Aug 28 02:15:04 PDT 2009 

Hi,

I just started testing Freeswitch, this works well. This is powerfull
and easy to administrate.

I just have one problem and one request. The request is BOUNTY-5: IMAP
integration of voicemail (I will try to propose a patch if this is
within my competencies)

The problem is with mod_fax not receiving any fax.

Relevant extension is:
    <extension name="fax2mail">
        <condition field="destination_number" expression="^(9998)$">
            <action application="set" data="fax_verbose=true"/>
            <action application="set" data="fax_disable_v17=false"/>
            <action application="set" data="fax_use_ecm=true"/>
            <action application="answer" />
            <action application="playback" data="silence_stream://2000"/>
            <action application="rxfax" data="/tmp/${uuid}.rxfax.tiff"/>
            <action application="hangup"/>
        </condition>
    </extension>

Test case is a 1-page fax coming from a Minolta printer connected to a
Cisco VG248 (via RJ11). The VG248 port is registred on a Cisco Call
Manager communicating with FS via a SIP trunk.

Log is attached:
- first try from 11:04:05 to 11:04:31
- 2nd try from 11:04:57 to 11:05:22
- 3rd try from 11:05:48 to 11:06:08

Do you need more information?

Regards

Mathieu Parent
-------------- next part --------------
2009-08-28 11:04:05.852705 [NOTICE] switch_channel.c:602 New Channel sofia/external/7629 at 85.0.30.241 [bd163f2c-93b1-11de-ae8e-27b1291d9722]
2009-08-28 11:04:05.852705 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_NEW
2009-08-28 11:04:05.852705 [DEBUG] switch_core_state_machine.c:404 (sofia/external/7629 at 85.0.30.241) State NEW
2009-08-28 11:04:05.852705 [DEBUG] sofia.c:3289 Channel sofia/external/7629 at 85.0.30.241 entering state [received][100]
2009-08-28 11:04:05.852705 [DEBUG] sofia.c:3296 Remote SDP:
v=0
o=CiscoSystemsCCM-SIP 2000 1000 IN IP4 85.0.30.241
s=SIP Call
c=IN IP4 85.0.30.240
t=0 0
m=audio 28086 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2009-08-28 11:04:05.852705 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:20]/[PCMU:0:8000:20]
2009-08-28 11:04:05.852705 [DEBUG] sofia_glue.c:2029 Set Codec sofia/external/7629 at 85.0.30.241 PCMU/8000 20 ms 160 samples
2009-08-28 11:04:05.852705 [DEBUG] sofia_glue.c:3031 Set 2833 dtmf payload to 101
2009-08-28 11:04:05.852705 [DEBUG] sofia.c:3455 (sofia/external/7629 at 85.0.30.241) State Change CS_NEW -> CS_INIT
2009-08-28 11:04:05.852705 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_INIT
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:481 (sofia/external/7629 at 85.0.30.241) State INIT
2009-08-28 11:04:05.856715 [DEBUG] mod_sofia.c:83 sofia/external/7629 at 85.0.30.241 SOFIA INIT
2009-08-28 11:04:05.856715 [DEBUG] mod_sofia.c:111 (sofia/external/7629 at 85.0.30.241) State Change CS_INIT -> CS_ROUTING
2009-08-28 11:04:05.856715 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:481 (sofia/external/7629 at 85.0.30.241) State INIT going to sleep
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_ROUTING
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:484 (sofia/external/7629 at 85.0.30.241) State ROUTING
2009-08-28 11:04:05.856715 [DEBUG] mod_sofia.c:130 sofia/external/7629 at 85.0.30.241 SOFIA ROUTING
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:78 sofia/external/7629 at 85.0.30.241 Standard ROUTING
2009-08-28 11:04:05.856715 [INFO] mod_dialplan_xml.c:315 Processing FAX D.I.C. 7629->9998 in context public
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->unloop] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->outside_call] continue=true
Dialplan: sofia/external/7629 at 85.0.30.241 Absolute Condition [outside_call]
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(outside_call=true)
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->call_debug] continue=true
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->public_extensions] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [public_extensions] destination_number(9998) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->vmain] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [vmain] destination_number(9998) =~ /^(9999)$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->fax2mail] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (PASS) [fax2mail] destination_number(9998) =~ /^(9998)$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(fax_verbose=true)
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(fax_disable_v17=false)
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(fax_use_ecm=true)
Dialplan: sofia/external/7629 at 85.0.30.241 Action answer()
Dialplan: sofia/external/7629 at 85.0.30.241 Action playback(silence_stream://2000)
Dialplan: sofia/external/7629 at 85.0.30.241 Action rxfax(/tmp/${uuid}.rxfax.tiff)
Dialplan: sofia/external/7629 at 85.0.30.241 Action hangup()
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:114 (sofia/external/7629 at 85.0.30.241) State Change CS_ROUTING -> CS_EXECUTE
2009-08-28 11:04:05.856715 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:484 (sofia/external/7629 at 85.0.30.241) State ROUTING going to sleep
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_EXECUTE
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:491 (sofia/external/7629 at 85.0.30.241) State EXECUTE
2009-08-28 11:04:05.856715 [DEBUG] mod_sofia.c:173 sofia/external/7629 at 85.0.30.241 SOFIA EXECUTE
2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:151 sofia/external/7629 at 85.0.30.241 Standard EXECUTE
EXECUTE sofia/external/7629 at 85.0.30.241 set(outside_call=true)
2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [outside_call]=[true]
EXECUTE sofia/external/7629 at 85.0.30.241 set(fax_verbose=true)
2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [fax_verbose]=[true]
EXECUTE sofia/external/7629 at 85.0.30.241 set(fax_disable_v17=false)
2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [fax_disable_v17]=[false]
EXECUTE sofia/external/7629 at 85.0.30.241 set(fax_use_ecm=true)
2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [fax_use_ecm]=[true]
EXECUTE sofia/external/7629 at 85.0.30.241 answer()
2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:649 sofia/external/7629 at 85.0.30.241 receive message [ANSWER]
2009-08-28 11:04:05.856715 [DEBUG] sofia_glue.c:2263 AUDIO RTP [sofia/external/7629 at 85.0.30.241] 10.30.15.137 port 31604 -> 85.0.30.240 port 28086 codec: 0 ms: 20
2009-08-28 11:04:05.856715 [DEBUG] switch_rtp.c:1138 Starting timer [soft] 160 bytes per 20ms
2009-08-28 11:04:05.860708 [DEBUG] mod_sofia.c:552 Local SDP sofia/external/7629 at 85.0.30.241:
v=0
o=FreeSWITCH 1251418641 1251418642 IN IP4 10.30.15.137
s=FreeSWITCH
c=IN IP4 10.30.15.137
t=0 0
m=audio 31604 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2009-08-28 11:04:05.860708 [DEBUG] switch_core_session.c:630 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:05.860708 [NOTICE] mod_dptools.c:649 Channel [sofia/external/7629 at 85.0.30.241] has been answered
2009-08-28 11:04:05.860708 [DEBUG] switch_channel.c:182 sofia/external/7629 at 85.0.30.241 receive message [AUDIO_SYNC]
EXECUTE sofia/external/7629 at 85.0.30.241 playback(silence_stream://2000)
2009-08-28 11:04:05.860708 [DEBUG] switch_ivr_play_say.c:1097 Codec Activated L16 at 8000hz 1 channels 20ms
2009-08-28 11:04:05.860708 [DEBUG] switch_core_io.c:649 sofia/external/7629 at 85.0.30.241 receive message [TRANSCODING_NECESSARY]
2009-08-28 11:04:05.860708 [DEBUG] sofia.c:3289 Channel sofia/external/7629 at 85.0.30.241 entering state [completed][200]
2009-08-28 11:04:05.872721 [DEBUG] sofia.c:3289 Channel sofia/external/7629 at 85.0.30.241 entering state [ready][200]
2009-08-28 11:04:07.868730 [DEBUG] switch_ivr_play_say.c:1391 done playing file
EXECUTE sofia/external/7629 at 85.0.30.241 rxfax(/tmp/bd163f2c-93b1-11de-ae8e-27b1291d9722.rxfax.tiff)
2009-08-28 11:04:07.868730 [DEBUG] mod_fax.c:591 Raw read codec activation Success L16 20000
2009-08-28 11:04:07.868730 [DEBUG] mod_fax.c:607 Raw write codec activation Success L16
2009-08-28 11:04:07.868730 [DEBUG] switch_channel.c:182 sofia/external/7629 at 85.0.30.241 receive message [AUDIO_SYNC]
2009-08-28 11:04:07.908721 [DEBUG] switch_core_io.c:232 sofia/external/7629 at 85.0.30.241 receive message [TRANSCODING_NECESSARY]
2009-08-28 11:04:08.468727 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1
2009-08-28 11:04:08.488736 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 1
2009-08-28 11:04:10.68454 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1
2009-08-28 11:04:10.568485 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 1
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_A_CED, state 1
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 FLOW T.30 Starting answer mode
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_A_CED to T30_PHASE_B_TX
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 1 to 17
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 FLOW T.30 Sending ident 'SpanDSP Fax Ident'
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  CSI without final frame tag
2009-08-28 11:04:10.948466 [DEBUG] mod_fax.c:137 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
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30 DIS:
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= 3G mobile network: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= V.8 capabilities: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Preferred octets: 256 octets
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Ready to transmit a fax document (polling): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..1.= Can receive fax: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= 2-D coding: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1%
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 10..= Recording length: Unlimited
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= T.6 coding: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= "Field not valid" supported: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Multiple selective polling: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Polled sub-address: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= T.43 coding: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Plane interleave: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Reserved for the use of extended voice coding set: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...1= R8x15.4lines/mm: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= 300x300pels/25.4mm: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Inch-based resolution preferred: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= Metric-based resolution preferred: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Selective polling: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Sub-addressing: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Password: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transmit a data file (polling): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Binary file transfer (BFT): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Document transfer mode (DTM): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Electronic data interchange (EDI): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Basic transfer mode (BTM): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transfer a character or mixed mode document (polling): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Character mode: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Mixed mode (Annex E/T.4): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Processable mode 26 (Rec. T.505): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Digital network capability: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Duplex capability: Half only
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= JPEG coding: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Full colour mode: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= 12bits/pel component: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= No subsampling (1:1:1): Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Custom illuminant: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Custom gamut range: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 1...= North American Letter (215.9mm x 279.4mm): Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= North American Legal (215.9mm x 355.6mm): Set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= Extension indicator: Not set
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  DIS with final frame tag
2009-08-28 11:04:12.528716 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  ff 13 80 00 ee fa c4 80 95 80 80 80 18
2009-08-28 11:04:12.988723 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:04:13.68696 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:04:13.68696 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_B_RX
2009-08-28 11:04:13.68696 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 4
2009-08-28 11:04:13.68696 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0
2009-08-28 11:04:13.68696 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4
2009-08-28 11:04:13.88698 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:04:13.108696 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:04:13.128697 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:04:13.148696 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:04:13.148696 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:04:13.168483 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:04:15.228722 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:04:15.728724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:04:16.528725 [DEBUG] mod_fax.c:137 FLOW T.30 T4 expired in phase T30_PHASE_B_RX, state 17
2009-08-28 11:04:16.528725 [DEBUG] mod_fax.c:137 FLOW T.30 Retry number 1
2009-08-28 11:04:16.528725 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_B_TX
2009-08-28 11:04:16.528725 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:04:16.528725 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4
2009-08-28 11:04:16.528725 [DEBUG] mod_fax.c:137 FLOW T.30 Sending ident 'SpanDSP Fax Ident'
2009-08-28 11:04:16.528725 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  CSI without final frame tag
2009-08-28 11:04:16.528725 [DEBUG] mod_fax.c:137 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
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30 DIS:
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= 3G mobile network: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= V.8 capabilities: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Preferred octets: 256 octets
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Ready to transmit a fax document (polling): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..1.= Can receive fax: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= 2-D coding: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1%
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... 10..= Recording length: Unlimited
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= T.6 coding: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= "Field not valid" supported: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Multiple selective polling: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Polled sub-address: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= T.43 coding: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Plane interleave: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Reserved for the use of extended voice coding set: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...1= R8x15.4lines/mm: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= 300x300pels/25.4mm: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Inch-based resolution preferred: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= Metric-based resolution preferred: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Selective polling: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Sub-addressing: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Password: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transmit a data file (polling): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Binary file transfer (BFT): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Document transfer mode (DTM): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Electronic data interchange (EDI): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Basic transfer mode (BTM): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transfer a character or mixed mode document (polling): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Character mode: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Mixed mode (Annex E/T.4): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Processable mode 26 (Rec. T.505): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Digital network capability: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Duplex capability: Half only
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= JPEG coding: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Full colour mode: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= 12bits/pel component: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= No subsampling (1:1:1): Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Custom illuminant: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Custom gamut range: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .... 1...= North American Letter (215.9mm x 279.4mm): Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= North American Legal (215.9mm x 355.6mm): Set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= Extension indicator: Not set
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  DIS with final frame tag
2009-08-28 11:04:18.108708 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  ff 13 80 00 ee fa c4 80 95 80 80 80 18
2009-08-28 11:04:18.588474 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:04:18.668474 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:04:18.668474 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_B_RX
2009-08-28 11:04:18.668474 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 4
2009-08-28 11:04:18.668474 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0
2009-08-28 11:04:18.668474 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4
2009-08-28 11:04:18.688478 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:04:18.708475 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:04:18.728726 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:04:18.748726 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:04:18.968729 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:04:19.188723 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:04:19.208726 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:04:19.508723 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 17
2009-08-28 11:04:19.508723 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4A
2009-08-28 11:04:20.528725 [DEBUG] mod_fax.c:137 FLOW T.30 Bad HDLC CRC received
2009-08-28 11:04:20.528725 [DEBUG] mod_fax.c:137 FLOW T.30 Bad CRC and timer is 7
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T4A (13920 remaining)
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  DCS with final frame tag
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  ff 13 83 00 62 f8 44
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30 In state 17
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30 DCS:
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= 3G mobile network: Not set
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..1.= Receive fax: Set
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   ..10 00..= Selected data signalling rate: V.17 14400bps
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= 2-D coding: Not set
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..00= Recording width: 215mm +- 1%
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .... 10..= Recording length: Unlimited
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .111 ....= Minimum scan line time: 0ms
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Frame size: 256 octets
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= T.6 coding: Set
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= Extension indicator: Not set
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30 Selected compression 3
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30 Get document at 14400bps, modem 7
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 17 to 7
2009-08-28 11:04:20.788727 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2
2009-08-28 11:04:20.848726 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7
2009-08-28 11:04:20.848726 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_C_NON_ECM_RX
2009-08-28 11:04:20.848726 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:04:20.848726 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 7
2009-08-28 11:04:20.848726 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0
2009-08-28 11:04:20.928727 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7
2009-08-28 11:04:20.928727 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7
2009-08-28 11:04:21.68725 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7
2009-08-28 11:04:21.128725 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7
2009-08-28 11:04:21.128725 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7
2009-08-28 11:04:21.128725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7
2009-08-28 11:04:21.128725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7
2009-08-28 11:04:21.248725 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state 7
2009-08-28 11:04:21.748711 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:04:22.168711 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:04:22.508710 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7
2009-08-28 11:04:22.808710 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:04:22.868712 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:04:23.648711 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:04:24.48712 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7
2009-08-28 11:04:24.68714 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:04:24.68714 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7
2009-08-28 11:04:27.108725 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7
2009-08-28 11:04:27.108725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7
2009-08-28 11:04:27.268725 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7
2009-08-28 11:04:27.468727 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 7
2009-08-28 11:04:27.468727 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2A
2009-08-28 11:04:28.648725 [DEBUG] mod_fax.c:137 FLOW T.30 Bad HDLC CRC received
2009-08-28 11:04:28.648725 [DEBUG] mod_fax.c:137 FLOW T.30 Bad CRC and timer is 3
2009-08-28 11:04:28.648725 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T2A (14720 remaining)
2009-08-28 11:04:28.928723 [DEBUG] mod_fax.c:137 FLOW T.30 Stop none (0 remaining)
2009-08-28 11:04:28.928723 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  DCS with final frame tag
2009-08-28 11:04:28.928723 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  ff 13 83 00 62 f8 44
2009-08-28 11:04:28.928723 [DEBUG] mod_fax.c:137 FLOW T.30 In state 7
2009-08-28 11:04:28.928723 [DEBUG] mod_fax.c:137 FLOW T.30 Unexpected DCS received in state 7
2009-08-28 11:04:28.928723 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 7 to 3
2009-08-28 11:04:28.928723 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  DCN with final frame tag
2009-08-28 11:04:28.928723 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  ff 13 fa
2009-08-28 11:04:28.928723 [DEBUG] mod_fax.c:137 FLOW FAX Switching from V.17 + V.21 to V.21 (-14.65dBm0)
2009-08-28 11:04:28.988725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 3
2009-08-28 11:04:28.988725 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_C_NON_ECM_RX to T30_PHASE_D_TX
2009-08-28 11:04:28.988725 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:04:28.988725 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4
2009-08-28 11:04:30.48729 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
2009-08-28 11:04:30.128724 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
2009-08-28 11:04:30.128724 [DEBUG] mod_fax.c:137 FLOW T.30 Disconnecting
2009-08-28 11:04:30.128724 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_E
2009-08-28 11:04:30.128724 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:04:30.128724 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 1
2009-08-28 11:04:30.128724 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 3 to 2
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_E, state 2
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:167 ==============================================================================
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:180 Fax processing not successful - result (13) Unexpected message received.
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:185 Remote station id: 
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:186 Local station id:  SpanDSP Fax Ident
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:187 Pages transferred: 0
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:189 Total fax pages:   0
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:190 Image resolution:  8031x7700
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:191 Transfer Rate:     14400
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:193 ECM status         on
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:194 remote country:   
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:195 remote vendor:    
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:196 remote model:     
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:198 ==============================================================================
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 2 to 32
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 8
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 8
2009-08-28 11:04:31.128724 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete
2009-08-28 11:04:31.148726 [DEBUG] switch_core_codec.c:122 Restore original codec.
EXECUTE sofia/external/7629 at 85.0.30.241 hangup()
2009-08-28 11:04:31.148726 [NOTICE] mod_dptools.c:633 Hangup sofia/external/7629 at 85.0.30.241 [CS_EXECUTE] [NORMAL_CLEARING]
2009-08-28 11:04:31.148726 [DEBUG] switch_channel.c:1683 Send signal sofia/external/7629 at 85.0.30.241 [KILL]
2009-08-28 11:04:31.148726 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:491 (sofia/external/7629 at 85.0.30.241) State EXECUTE going to sleep
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_HANGUP
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:434 (sofia/external/7629 at 85.0.30.241) State HANGUP
2009-08-28 11:04:31.148726 [DEBUG] mod_sofia.c:338 Channel sofia/external/7629 at 85.0.30.241 hanging up, cause: NORMAL_CLEARING
2009-08-28 11:04:31.148726 [DEBUG] mod_sofia.c:396 Sending BYE to sofia/external/7629 at 85.0.30.241
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:46 sofia/external/7629 at 85.0.30.241 Standard HANGUP, cause: NORMAL_CLEARING
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:434 (sofia/external/7629 at 85.0.30.241) State HANGUP going to sleep
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:476 (sofia/external/7629 at 85.0.30.241) State Change CS_HANGUP -> CS_REPORTING
2009-08-28 11:04:31.148726 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_REPORTING
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:612 (sofia/external/7629 at 85.0.30.241) State REPORTING
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:53 sofia/external/7629 at 85.0.30.241 Standard REPORTING, cause: NORMAL_CLEARING
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:612 (sofia/external/7629 at 85.0.30.241) State REPORTING going to sleep
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:411 (sofia/external/7629 at 85.0.30.241) State Change CS_REPORTING -> CS_DESTROY
2009-08-28 11:04:31.148726 [DEBUG] switch_core_session.c:1068 Session 24 (sofia/external/7629 at 85.0.30.241) Locked, Waiting on external entities
2009-08-28 11:04:31.148726 [NOTICE] switch_core_session.c:1086 Session 24 (sofia/external/7629 at 85.0.30.241) Ended
2009-08-28 11:04:31.148726 [NOTICE] switch_core_session.c:1088 Close Channel sofia/external/7629 at 85.0.30.241 [CS_DESTROY]
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629 at 85.0.30.241) State DESTROY
2009-08-28 11:04:31.148726 [DEBUG] mod_sofia.c:255 sofia/external/7629 at 85.0.30.241 SOFIA DESTROY
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:60 sofia/external/7629 at 85.0.30.241 Standard DESTROY
2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629 at 85.0.30.241) State DESTROY going to sleep
2009-08-28 11:04:57.372710 [NOTICE] switch_channel.c:602 New Channel sofia/external/7629 at 85.0.30.241 [dbcb8bfc-93b1-11de-ae8e-27b1291d9722]
2009-08-28 11:04:57.372710 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_NEW
2009-08-28 11:04:57.372710 [DEBUG] sofia.c:3289 Channel sofia/external/7629 at 85.0.30.241 entering state [received][100]
2009-08-28 11:04:57.372710 [DEBUG] sofia.c:3296 Remote SDP:
v=0
o=CiscoSystemsCCM-SIP 2000 1000 IN IP4 85.0.30.241
s=SIP Call
c=IN IP4 85.0.30.240
t=0 0
m=audio 28090 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2009-08-28 11:04:57.372710 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:20]/[PCMU:0:8000:20]
2009-08-28 11:04:57.372710 [DEBUG] sofia_glue.c:2029 Set Codec sofia/external/7629 at 85.0.30.241 PCMU/8000 20 ms 160 samples
2009-08-28 11:04:57.372710 [DEBUG] switch_core_state_machine.c:404 (sofia/external/7629 at 85.0.30.241) State NEW
2009-08-28 11:04:57.372710 [DEBUG] sofia_glue.c:3031 Set 2833 dtmf payload to 101
2009-08-28 11:04:57.372710 [DEBUG] sofia.c:3455 (sofia/external/7629 at 85.0.30.241) State Change CS_NEW -> CS_INIT
2009-08-28 11:04:57.372710 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_INIT
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:481 (sofia/external/7629 at 85.0.30.241) State INIT
2009-08-28 11:04:57.376739 [DEBUG] mod_sofia.c:83 sofia/external/7629 at 85.0.30.241 SOFIA INIT
2009-08-28 11:04:57.376739 [DEBUG] mod_sofia.c:111 (sofia/external/7629 at 85.0.30.241) State Change CS_INIT -> CS_ROUTING
2009-08-28 11:04:57.376739 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:481 (sofia/external/7629 at 85.0.30.241) State INIT going to sleep
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_ROUTING
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:484 (sofia/external/7629 at 85.0.30.241) State ROUTING
2009-08-28 11:04:57.376739 [DEBUG] mod_sofia.c:130 sofia/external/7629 at 85.0.30.241 SOFIA ROUTING
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:78 sofia/external/7629 at 85.0.30.241 Standard ROUTING
2009-08-28 11:04:57.376739 [INFO] mod_dialplan_xml.c:315 Processing FAX D.I.C. 7629->9998 in context public
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->unloop] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->outside_call] continue=true
Dialplan: sofia/external/7629 at 85.0.30.241 Absolute Condition [outside_call]
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(outside_call=true)
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->call_debug] continue=true
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->public_extensions] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [public_extensions] destination_number(9998) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->vmain] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [vmain] destination_number(9998) =~ /^(9999)$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->fax2mail] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (PASS) [fax2mail] destination_number(9998) =~ /^(9998)$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(fax_verbose=true)
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(fax_disable_v17=false)
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(fax_use_ecm=true)
Dialplan: sofia/external/7629 at 85.0.30.241 Action answer()
Dialplan: sofia/external/7629 at 85.0.30.241 Action playback(silence_stream://2000)
Dialplan: sofia/external/7629 at 85.0.30.241 Action rxfax(/tmp/${uuid}.rxfax.tiff)
Dialplan: sofia/external/7629 at 85.0.30.241 Action hangup()
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:114 (sofia/external/7629 at 85.0.30.241) State Change CS_ROUTING -> CS_EXECUTE
2009-08-28 11:04:57.376739 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:484 (sofia/external/7629 at 85.0.30.241) State ROUTING going to sleep
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_EXECUTE
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:491 (sofia/external/7629 at 85.0.30.241) State EXECUTE
2009-08-28 11:04:57.376739 [DEBUG] mod_sofia.c:173 sofia/external/7629 at 85.0.30.241 SOFIA EXECUTE
2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:151 sofia/external/7629 at 85.0.30.241 Standard EXECUTE
EXECUTE sofia/external/7629 at 85.0.30.241 set(outside_call=true)
2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [outside_call]=[true]
EXECUTE sofia/external/7629 at 85.0.30.241 set(fax_verbose=true)
2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [fax_verbose]=[true]
EXECUTE sofia/external/7629 at 85.0.30.241 set(fax_disable_v17=false)
2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [fax_disable_v17]=[false]
EXECUTE sofia/external/7629 at 85.0.30.241 set(fax_use_ecm=true)
2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [fax_use_ecm]=[true]
EXECUTE sofia/external/7629 at 85.0.30.241 answer()
2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:649 sofia/external/7629 at 85.0.30.241 receive message [ANSWER]
2009-08-28 11:04:57.376739 [DEBUG] sofia_glue.c:2263 AUDIO RTP [sofia/external/7629 at 85.0.30.241] 10.30.15.137 port 32446 -> 85.0.30.240 port 28090 codec: 0 ms: 20
2009-08-28 11:04:57.376739 [DEBUG] switch_rtp.c:1138 Starting timer [soft] 160 bytes per 20ms
2009-08-28 11:04:57.380744 [DEBUG] mod_sofia.c:552 Local SDP sofia/external/7629 at 85.0.30.241:
v=0
o=FreeSWITCH 1251417851 1251417852 IN IP4 10.30.15.137
s=FreeSWITCH
c=IN IP4 10.30.15.137
t=0 0
m=audio 32446 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2009-08-28 11:04:57.380744 [DEBUG] switch_core_session.c:630 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:04:57.380744 [NOTICE] mod_dptools.c:649 Channel [sofia/external/7629 at 85.0.30.241] has been answered
2009-08-28 11:04:57.380744 [DEBUG] switch_channel.c:182 sofia/external/7629 at 85.0.30.241 receive message [AUDIO_SYNC]
2009-08-28 11:04:57.380744 [DEBUG] sofia.c:3289 Channel sofia/external/7629 at 85.0.30.241 entering state [completed][200]
EXECUTE sofia/external/7629 at 85.0.30.241 playback(silence_stream://2000)
2009-08-28 11:04:57.380744 [DEBUG] switch_ivr_play_say.c:1097 Codec Activated L16 at 8000hz 1 channels 20ms
2009-08-28 11:04:57.380744 [DEBUG] switch_core_io.c:649 sofia/external/7629 at 85.0.30.241 receive message [TRANSCODING_NECESSARY]
2009-08-28 11:04:57.388729 [DEBUG] sofia.c:3289 Channel sofia/external/7629 at 85.0.30.241 entering state [ready][200]
2009-08-28 11:04:59.388741 [DEBUG] switch_ivr_play_say.c:1391 done playing file
EXECUTE sofia/external/7629 at 85.0.30.241 rxfax(/tmp/dbcb8bfc-93b1-11de-ae8e-27b1291d9722.rxfax.tiff)
2009-08-28 11:04:59.388741 [DEBUG] mod_fax.c:591 Raw read codec activation Success L16 20000
2009-08-28 11:04:59.388741 [DEBUG] mod_fax.c:607 Raw write codec activation Success L16
2009-08-28 11:04:59.388741 [DEBUG] switch_channel.c:182 sofia/external/7629 at 85.0.30.241 receive message [AUDIO_SYNC]
2009-08-28 11:04:59.428463 [DEBUG] switch_core_io.c:232 sofia/external/7629 at 85.0.30.241 receive message [TRANSCODING_NECESSARY]
2009-08-28 11:04:59.988724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1
2009-08-28 11:05:00.8724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 1
2009-08-28 11:05:01.568724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1
2009-08-28 11:05:02.68697 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 1
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_A_CED, state 1
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 FLOW T.30 Starting answer mode
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_A_CED to T30_PHASE_B_TX
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 1 to 17
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 FLOW T.30 Sending ident 'SpanDSP Fax Ident'
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  CSI without final frame tag
2009-08-28 11:05:02.468726 [DEBUG] mod_fax.c:137 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
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30 DIS:
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= 3G mobile network: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= V.8 capabilities: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Preferred octets: 256 octets
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Ready to transmit a fax document (polling): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..1.= Can receive fax: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= 2-D coding: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1%
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... 10..= Recording length: Unlimited
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= T.6 coding: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= "Field not valid" supported: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Multiple selective polling: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Polled sub-address: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= T.43 coding: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Plane interleave: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Reserved for the use of extended voice coding set: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...1= R8x15.4lines/mm: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= 300x300pels/25.4mm: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Inch-based resolution preferred: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= Metric-based resolution preferred: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Selective polling: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Sub-addressing: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Password: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transmit a data file (polling): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Binary file transfer (BFT): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Document transfer mode (DTM): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Electronic data interchange (EDI): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Basic transfer mode (BTM): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transfer a character or mixed mode document (polling): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Character mode: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Mixed mode (Annex E/T.4): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Processable mode 26 (Rec. T.505): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Digital network capability: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Duplex capability: Half only
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= JPEG coding: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Full colour mode: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= 12bits/pel component: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= No subsampling (1:1:1): Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Custom illuminant: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Custom gamut range: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .... 1...= North American Letter (215.9mm x 279.4mm): Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= North American Legal (215.9mm x 355.6mm): Set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= Extension indicator: Not set
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  DIS with final frame tag
2009-08-28 11:05:04.48696 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  ff 13 80 00 ee fa c4 80 95 80 80 80 18
2009-08-28 11:05:04.508695 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:05:04.588710 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:05:04.588710 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_B_RX
2009-08-28 11:05:04.588710 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 4
2009-08-28 11:05:04.588710 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0
2009-08-28 11:05:04.588710 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4
2009-08-28 11:05:04.608711 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:04.628710 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:04.648711 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:04.648711 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:04.668726 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:04.688724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:06.748695 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:07.248745 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:08.48695 [DEBUG] mod_fax.c:137 FLOW T.30 T4 expired in phase T30_PHASE_B_RX, state 17
2009-08-28 11:05:08.48695 [DEBUG] mod_fax.c:137 FLOW T.30 Retry number 1
2009-08-28 11:05:08.48695 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_B_TX
2009-08-28 11:05:08.48695 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:05:08.48695 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4
2009-08-28 11:05:08.48695 [DEBUG] mod_fax.c:137 FLOW T.30 Sending ident 'SpanDSP Fax Ident'
2009-08-28 11:05:08.48695 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  CSI without final frame tag
2009-08-28 11:05:08.48695 [DEBUG] mod_fax.c:137 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
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30 DIS:
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= 3G mobile network: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= V.8 capabilities: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Preferred octets: 256 octets
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Ready to transmit a fax document (polling): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..1.= Can receive fax: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= 2-D coding: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1%
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... 10..= Recording length: Unlimited
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= T.6 coding: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= "Field not valid" supported: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Multiple selective polling: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Polled sub-address: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= T.43 coding: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Plane interleave: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Reserved for the use of extended voice coding set: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...1= R8x15.4lines/mm: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= 300x300pels/25.4mm: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Inch-based resolution preferred: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= Metric-based resolution preferred: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Selective polling: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Sub-addressing: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Password: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transmit a data file (polling): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Binary file transfer (BFT): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Document transfer mode (DTM): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Electronic data interchange (EDI): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Basic transfer mode (BTM): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transfer a character or mixed mode document (polling): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Character mode: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Mixed mode (Annex E/T.4): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Processable mode 26 (Rec. T.505): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Digital network capability: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Duplex capability: Half only
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= JPEG coding: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Full colour mode: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= 12bits/pel component: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= No subsampling (1:1:1): Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Custom illuminant: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Custom gamut range: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .... 1...= North American Letter (215.9mm x 279.4mm): Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= North American Legal (215.9mm x 355.6mm): Set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= Extension indicator: Not set
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  DIS with final frame tag
2009-08-28 11:05:09.628461 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  ff 13 80 00 ee fa c4 80 95 80 80 80 18
2009-08-28 11:05:10.108472 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:05:10.188469 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:05:10.188469 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_B_RX
2009-08-28 11:05:10.188469 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 4
2009-08-28 11:05:10.188469 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0
2009-08-28 11:05:10.188469 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4
2009-08-28 11:05:10.208465 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:10.228473 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:10.228473 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:10.248465 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:10.268468 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:10.268468 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:10.288466 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:10.288466 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:10.468464 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:10.688461 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 17
2009-08-28 11:05:10.688461 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4A
2009-08-28 11:05:10.788458 [DEBUG] mod_fax.c:137 FLOW T.30 Bad HDLC CRC received
2009-08-28 11:05:10.788458 [DEBUG] mod_fax.c:137 FLOW T.30 Bad CRC and timer is 7
2009-08-28 11:05:10.888470 [DEBUG] mod_fax.c:137 FLOW T.30 Bad HDLC CRC received
2009-08-28 11:05:10.888470 [DEBUG] mod_fax.c:137 FLOW T.30 Bad CRC and timer is 7
2009-08-28 11:05:12.28461 [DEBUG] mod_fax.c:137 FLOW T.30 Bad HDLC CRC received
2009-08-28 11:05:12.28461 [DEBUG] mod_fax.c:137 FLOW T.30 Bad CRC and timer is 7
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T4A (11840 remaining)
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  DCS with final frame tag
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  ff 13 83 00 62 f8 44
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30 In state 17
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30 DCS:
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= 3G mobile network: Not set
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..1.= Receive fax: Set
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   ..10 00..= Selected data signalling rate: V.17 14400bps
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= 2-D coding: Not set
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..00= Recording width: 215mm +- 1%
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .... 10..= Recording length: Unlimited
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .111 ....= Minimum scan line time: 0ms
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Frame size: 256 octets
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= T.6 coding: Set
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= Extension indicator: Not set
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30 Selected compression 3
2009-08-28 11:05:12.308695 [DEBUG] mod_fax.c:137 FLOW T.30 Get document at 14400bps, modem 7
2009-08-28 11:05:12.320684 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 17 to 7
2009-08-28 11:05:12.320684 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2
2009-08-28 11:05:12.368695 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7
2009-08-28 11:05:12.368695 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_C_NON_ECM_RX
2009-08-28 11:05:12.368695 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:05:12.368695 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 7
2009-08-28 11:05:12.368695 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0
2009-08-28 11:05:12.428696 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7
2009-08-28 11:05:12.428696 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7
2009-08-28 11:05:12.588696 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7
2009-08-28 11:05:12.628696 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7
2009-08-28 11:05:12.628696 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7
2009-08-28 11:05:12.628696 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7
2009-08-28 11:05:12.628696 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7
2009-08-28 11:05:12.748696 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state 7
2009-08-28 11:05:13.268481 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:05:14.8720 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7
2009-08-28 11:05:14.328710 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:05:14.648695 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:05:15.568732 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7
2009-08-28 11:05:15.568732 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7
2009-08-28 11:05:18.608475 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7
2009-08-28 11:05:18.608475 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7
2009-08-28 11:05:18.748726 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7
2009-08-28 11:05:19.8726 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 7
2009-08-28 11:05:19.8726 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2A
2009-08-28 11:05:20.168726 [DEBUG] mod_fax.c:137 FLOW T.30 Bad HDLC CRC received
2009-08-28 11:05:20.168726 [DEBUG] mod_fax.c:137 FLOW T.30 Bad CRC and timer is 3
2009-08-28 11:05:20.168726 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T2A (14880 remaining)
2009-08-28 11:05:20.448723 [DEBUG] mod_fax.c:137 FLOW T.30 Stop none (0 remaining)
2009-08-28 11:05:20.448723 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  DCS with final frame tag
2009-08-28 11:05:20.448723 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  ff 13 83 00 62 f8 44
2009-08-28 11:05:20.448723 [DEBUG] mod_fax.c:137 FLOW T.30 In state 7
2009-08-28 11:05:20.448723 [DEBUG] mod_fax.c:137 FLOW T.30 Unexpected DCS received in state 7
2009-08-28 11:05:20.448723 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 7 to 3
2009-08-28 11:05:20.448723 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  DCN with final frame tag
2009-08-28 11:05:20.448723 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  ff 13 fa
2009-08-28 11:05:20.448723 [DEBUG] mod_fax.c:137 FLOW FAX Switching from V.17 + V.21 to V.21 (-14.62dBm0)
2009-08-28 11:05:20.488724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 3
2009-08-28 11:05:20.488724 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_C_NON_ECM_RX to T30_PHASE_D_TX
2009-08-28 11:05:20.488724 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:05:20.488724 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4
2009-08-28 11:05:21.548725 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
2009-08-28 11:05:21.628731 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
2009-08-28 11:05:21.628731 [DEBUG] mod_fax.c:137 FLOW T.30 Disconnecting
2009-08-28 11:05:21.628731 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_E
2009-08-28 11:05:21.628731 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:05:21.628731 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 1
2009-08-28 11:05:21.628731 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 3 to 2
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_E, state 2
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:167 ==============================================================================
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:180 Fax processing not successful - result (13) Unexpected message received.
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:185 Remote station id: 
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:186 Local station id:  SpanDSP Fax Ident
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:187 Pages transferred: 0
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:189 Total fax pages:   0
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:190 Image resolution:  8031x7700
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:191 Transfer Rate:     14400
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:193 ECM status         on
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:194 remote country:   
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:195 remote vendor:    
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:196 remote model:     
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:198 ==============================================================================
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 2 to 32
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 8
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 8
2009-08-28 11:05:22.628725 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete
2009-08-28 11:05:22.648728 [DEBUG] switch_core_codec.c:122 Restore original codec.
EXECUTE sofia/external/7629 at 85.0.30.241 hangup()
2009-08-28 11:05:22.648728 [NOTICE] mod_dptools.c:633 Hangup sofia/external/7629 at 85.0.30.241 [CS_EXECUTE] [NORMAL_CLEARING]
2009-08-28 11:05:22.648728 [DEBUG] switch_channel.c:1683 Send signal sofia/external/7629 at 85.0.30.241 [KILL]
2009-08-28 11:05:22.648728 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:491 (sofia/external/7629 at 85.0.30.241) State EXECUTE going to sleep
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_HANGUP
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:434 (sofia/external/7629 at 85.0.30.241) State HANGUP
2009-08-28 11:05:22.648728 [DEBUG] mod_sofia.c:338 Channel sofia/external/7629 at 85.0.30.241 hanging up, cause: NORMAL_CLEARING
2009-08-28 11:05:22.648728 [DEBUG] mod_sofia.c:396 Sending BYE to sofia/external/7629 at 85.0.30.241
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:46 sofia/external/7629 at 85.0.30.241 Standard HANGUP, cause: NORMAL_CLEARING
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:434 (sofia/external/7629 at 85.0.30.241) State HANGUP going to sleep
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:476 (sofia/external/7629 at 85.0.30.241) State Change CS_HANGUP -> CS_REPORTING
2009-08-28 11:05:22.648728 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_REPORTING
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:612 (sofia/external/7629 at 85.0.30.241) State REPORTING
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:53 sofia/external/7629 at 85.0.30.241 Standard REPORTING, cause: NORMAL_CLEARING
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:612 (sofia/external/7629 at 85.0.30.241) State REPORTING going to sleep
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:411 (sofia/external/7629 at 85.0.30.241) State Change CS_REPORTING -> CS_DESTROY
2009-08-28 11:05:22.648728 [DEBUG] switch_core_session.c:1068 Session 25 (sofia/external/7629 at 85.0.30.241) Locked, Waiting on external entities
2009-08-28 11:05:22.648728 [NOTICE] switch_core_session.c:1086 Session 25 (sofia/external/7629 at 85.0.30.241) Ended
2009-08-28 11:05:22.648728 [NOTICE] switch_core_session.c:1088 Close Channel sofia/external/7629 at 85.0.30.241 [CS_DESTROY]
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629 at 85.0.30.241) State DESTROY
2009-08-28 11:05:22.648728 [DEBUG] mod_sofia.c:255 sofia/external/7629 at 85.0.30.241 SOFIA DESTROY
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:60 sofia/external/7629 at 85.0.30.241 Standard DESTROY
2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629 at 85.0.30.241) State DESTROY going to sleep
2009-08-28 11:05:48.912723 [NOTICE] switch_channel.c:602 New Channel sofia/external/7629 at 85.0.30.241 [fa83c460-93b1-11de-ae8e-27b1291d9722]
2009-08-28 11:05:48.912723 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_NEW
2009-08-28 11:05:48.912723 [DEBUG] sofia.c:3289 Channel sofia/external/7629 at 85.0.30.241 entering state [received][100]
2009-08-28 11:05:48.912723 [DEBUG] sofia.c:3296 Remote SDP:
v=0
o=CiscoSystemsCCM-SIP 2000 1000 IN IP4 85.0.30.241
s=SIP Call
c=IN IP4 85.0.30.240
t=0 0
m=audio 28094 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2009-08-28 11:05:48.912723 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:20]/[PCMU:0:8000:20]
2009-08-28 11:05:48.912723 [DEBUG] sofia_glue.c:2029 Set Codec sofia/external/7629 at 85.0.30.241 PCMU/8000 20 ms 160 samples
2009-08-28 11:05:48.912723 [DEBUG] switch_core_state_machine.c:404 (sofia/external/7629 at 85.0.30.241) State NEW
2009-08-28 11:05:48.912723 [DEBUG] sofia_glue.c:3031 Set 2833 dtmf payload to 101
2009-08-28 11:05:48.912723 [DEBUG] sofia.c:3455 (sofia/external/7629 at 85.0.30.241) State Change CS_NEW -> CS_INIT
2009-08-28 11:05:48.912723 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_INIT
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:481 (sofia/external/7629 at 85.0.30.241) State INIT
2009-08-28 11:05:48.916860 [DEBUG] mod_sofia.c:83 sofia/external/7629 at 85.0.30.241 SOFIA INIT
2009-08-28 11:05:48.916860 [DEBUG] mod_sofia.c:111 (sofia/external/7629 at 85.0.30.241) State Change CS_INIT -> CS_ROUTING
2009-08-28 11:05:48.916860 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:481 (sofia/external/7629 at 85.0.30.241) State INIT going to sleep
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_ROUTING
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:484 (sofia/external/7629 at 85.0.30.241) State ROUTING
2009-08-28 11:05:48.916860 [DEBUG] mod_sofia.c:130 sofia/external/7629 at 85.0.30.241 SOFIA ROUTING
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:78 sofia/external/7629 at 85.0.30.241 Standard ROUTING
2009-08-28 11:05:48.916860 [INFO] mod_dialplan_xml.c:315 Processing FAX D.I.C. 7629->9998 in context public
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->unloop] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->outside_call] continue=true
Dialplan: sofia/external/7629 at 85.0.30.241 Absolute Condition [outside_call]
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(outside_call=true)
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->call_debug] continue=true
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->public_extensions] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [public_extensions] destination_number(9998) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->vmain] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (FAIL) [vmain] destination_number(9998) =~ /^(9999)$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 parsing [public->fax2mail] continue=false
Dialplan: sofia/external/7629 at 85.0.30.241 Regex (PASS) [fax2mail] destination_number(9998) =~ /^(9998)$/ break=on-false
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(fax_verbose=true)
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(fax_disable_v17=false)
Dialplan: sofia/external/7629 at 85.0.30.241 Action set(fax_use_ecm=true)
Dialplan: sofia/external/7629 at 85.0.30.241 Action answer()
Dialplan: sofia/external/7629 at 85.0.30.241 Action playback(silence_stream://2000)
Dialplan: sofia/external/7629 at 85.0.30.241 Action rxfax(/tmp/${uuid}.rxfax.tiff)
Dialplan: sofia/external/7629 at 85.0.30.241 Action hangup()
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:114 (sofia/external/7629 at 85.0.30.241) State Change CS_ROUTING -> CS_EXECUTE
2009-08-28 11:05:48.916860 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:484 (sofia/external/7629 at 85.0.30.241) State ROUTING going to sleep
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_EXECUTE
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:491 (sofia/external/7629 at 85.0.30.241) State EXECUTE
2009-08-28 11:05:48.916860 [DEBUG] mod_sofia.c:173 sofia/external/7629 at 85.0.30.241 SOFIA EXECUTE
2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:151 sofia/external/7629 at 85.0.30.241 Standard EXECUTE
EXECUTE sofia/external/7629 at 85.0.30.241 set(outside_call=true)
2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [outside_call]=[true]
EXECUTE sofia/external/7629 at 85.0.30.241 set(fax_verbose=true)
2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [fax_verbose]=[true]
EXECUTE sofia/external/7629 at 85.0.30.241 set(fax_disable_v17=false)
2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [fax_disable_v17]=[false]
EXECUTE sofia/external/7629 at 85.0.30.241 set(fax_use_ecm=true)
2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:748 sofia/external/7629 at 85.0.30.241 SET [fax_use_ecm]=[true]
EXECUTE sofia/external/7629 at 85.0.30.241 answer()
2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:649 sofia/external/7629 at 85.0.30.241 receive message [ANSWER]
2009-08-28 11:05:48.916860 [DEBUG] sofia_glue.c:2263 AUDIO RTP [sofia/external/7629 at 85.0.30.241] 10.30.15.137 port 24154 -> 85.0.30.240 port 28094 codec: 0 ms: 20
2009-08-28 11:05:48.916860 [DEBUG] switch_rtp.c:1138 Starting timer [soft] 160 bytes per 20ms
2009-08-28 11:05:48.920709 [DEBUG] mod_sofia.c:552 Local SDP sofia/external/7629 at 85.0.30.241:
v=0
o=FreeSWITCH 1251426194 1251426195 IN IP4 10.30.15.137
s=FreeSWITCH
c=IN IP4 10.30.15.137
t=0 0
m=audio 24154 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2009-08-28 11:05:48.920709 [DEBUG] switch_core_session.c:630 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:05:48.920709 [NOTICE] mod_dptools.c:649 Channel [sofia/external/7629 at 85.0.30.241] has been answered
2009-08-28 11:05:48.920709 [DEBUG] switch_channel.c:182 sofia/external/7629 at 85.0.30.241 receive message [AUDIO_SYNC]
2009-08-28 11:05:48.920709 [DEBUG] sofia.c:3289 Channel sofia/external/7629 at 85.0.30.241 entering state [completed][200]
EXECUTE sofia/external/7629 at 85.0.30.241 playback(silence_stream://2000)
2009-08-28 11:05:48.920709 [DEBUG] switch_ivr_play_say.c:1097 Codec Activated L16 at 8000hz 1 channels 20ms
2009-08-28 11:05:48.920709 [DEBUG] switch_core_io.c:649 sofia/external/7629 at 85.0.30.241 receive message [TRANSCODING_NECESSARY]
2009-08-28 11:05:48.928705 [DEBUG] sofia.c:3289 Channel sofia/external/7629 at 85.0.30.241 entering state [ready][200]
2009-08-28 11:05:50.928734 [DEBUG] switch_ivr_play_say.c:1391 done playing file
EXECUTE sofia/external/7629 at 85.0.30.241 rxfax(/tmp/fa83c460-93b1-11de-ae8e-27b1291d9722.rxfax.tiff)
2009-08-28 11:05:50.928734 [DEBUG] mod_fax.c:591 Raw read codec activation Success L16 20000
2009-08-28 11:05:50.928734 [DEBUG] mod_fax.c:607 Raw write codec activation Success L16
2009-08-28 11:05:50.928734 [DEBUG] switch_channel.c:182 sofia/external/7629 at 85.0.30.241 receive message [AUDIO_SYNC]
2009-08-28 11:05:50.968739 [DEBUG] switch_core_io.c:232 sofia/external/7629 at 85.0.30.241 receive message [TRANSCODING_NECESSARY]
2009-08-28 11:05:51.548728 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1
2009-08-28 11:05:51.548728 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 1
2009-08-28 11:05:53.128723 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1
2009-08-28 11:05:53.628727 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 1
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_A_CED, state 1
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 FLOW T.30 Starting answer mode
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_A_CED to T30_PHASE_B_TX
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 1 to 17
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 FLOW T.30 Sending ident 'SpanDSP Fax Ident'
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  CSI without final frame tag
2009-08-28 11:05:54.8726 [DEBUG] mod_fax.c:137 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
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30 DIS:
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= 3G mobile network: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= V.8 capabilities: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Preferred octets: 256 octets
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Ready to transmit a fax document (polling): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..1.= Can receive fax: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= 2-D coding: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1%
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 10..= Recording length: Unlimited
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= T.6 coding: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= "Field not valid" supported: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Multiple selective polling: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Polled sub-address: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= T.43 coding: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Plane interleave: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Reserved for the use of extended voice coding set: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...1= R8x15.4lines/mm: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= 300x300pels/25.4mm: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Inch-based resolution preferred: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= Metric-based resolution preferred: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Selective polling: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Sub-addressing: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Password: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transmit a data file (polling): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Binary file transfer (BFT): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Document transfer mode (DTM): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Electronic data interchange (EDI): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Basic transfer mode (BTM): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Ready to transfer a character or mixed mode document (polling): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Character mode: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Mixed mode (Annex E/T.4): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Processable mode 26 (Rec. T.505): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Digital network capability: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Duplex capability: Half only
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= JPEG coding: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ...0 ....= Full colour mode: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= 12bits/pel component: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= No subsampling (1:1:1): Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Custom illuminant: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Custom gamut range: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .... 1...= North American Letter (215.9mm x 279.4mm): Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ...1 ....= North American Legal (215.9mm x 355.6mm): Set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= Extension indicator: Not set
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  DIS with final frame tag
2009-08-28 11:05:55.588716 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  ff 13 80 00 ee fa c4 80 95 80 80 80 18
2009-08-28 11:05:56.48725 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:05:56.128732 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17
2009-08-28 11:05:56.128732 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_B_RX
2009-08-28 11:05:56.128732 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 4
2009-08-28 11:05:56.128732 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0
2009-08-28 11:05:56.128732 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4
2009-08-28 11:05:56.148725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:56.148725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:56.148725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:56.168727 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:56.168727 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:56.208724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:56.228725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:56.228725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:56.248726 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:56.268724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2009-08-28 11:05:56.448723 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2009-08-28 11:05:56.668724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 17
2009-08-28 11:05:56.668724 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4A
2009-08-28 11:05:56.748724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 17
2009-08-28 11:05:56.928724 [DEBUG] mod_fax.c:137 FLOW T.30 Bad HDLC CRC received
2009-08-28 11:05:56.928724 [DEBUG] mod_fax.c:137 FLOW T.30 Bad CRC and timer is 7
2009-08-28 11:05:58.8714 [DEBUG] mod_fax.c:137 FLOW T.30 Bad HDLC CRC received
2009-08-28 11:05:58.8714 [DEBUG] mod_fax.c:137 FLOW T.30 Bad CRC and timer is 7
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T4A (11840 remaining)
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  DCS with final frame tag
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  ff 13 83 00 62 f8 44
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30 In state 17
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30 DCS:
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= 3G mobile network: Not set
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..1.= Receive fax: Set
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   ..10 00..= Selected data signalling rate: V.17 14400bps
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= 2-D coding: Not set
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..00= Recording width: 215mm +- 1%
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .... 10..= Recording length: Unlimited
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .111 ....= Minimum scan line time: 0ms
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   1... ....= Extension indicator: Set
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .... 0...= Frame size: 256 octets
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   .1.. ....= T.6 coding: Set
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30   0... ....= Extension indicator: Not set
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30 Selected compression 3
2009-08-28 11:05:58.288715 [DEBUG] mod_fax.c:137 FLOW T.30 Get document at 14400bps, modem 7
2009-08-28 11:05:58.300704 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 17 to 7
2009-08-28 11:05:58.300704 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2
2009-08-28 11:05:58.348715 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7
2009-08-28 11:05:58.348715 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_C_NON_ECM_RX
2009-08-28 11:05:58.348715 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:05:58.348715 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 7
2009-08-28 11:05:58.348715 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0
2009-08-28 11:05:58.408715 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7
2009-08-28 11:05:58.408715 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7
2009-08-28 11:05:58.568726 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7
2009-08-28 11:05:58.608717 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7
2009-08-28 11:05:58.608717 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7
2009-08-28 11:05:58.608717 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7
2009-08-28 11:05:58.608717 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7
2009-08-28 11:05:58.748714 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state 7
2009-08-28 11:05:59.248723 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:05:59.648725 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:06:00.48734 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7
2009-08-28 11:06:00.308724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7
2009-08-28 11:06:01.548728 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7
2009-08-28 11:06:01.548728 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7
2009-08-28 11:06:04.588723 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7
2009-08-28 11:06:04.588723 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7
2009-08-28 11:06:04.728724 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7
2009-08-28 11:06:04.828724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 7
2009-08-28 11:06:04.828724 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2A
2009-08-28 11:06:06.148723 [DEBUG] mod_fax.c:137 FLOW T.30 Bad HDLC CRC received
2009-08-28 11:06:06.148723 [DEBUG] mod_fax.c:137 FLOW T.30 Bad CRC and timer is 3
2009-08-28 11:06:06.148723 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T2A (13760 remaining)
2009-08-28 11:06:06.428724 [DEBUG] mod_fax.c:137 FLOW T.30 Stop none (0 remaining)
2009-08-28 11:06:06.428724 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  DCS with final frame tag
2009-08-28 11:06:06.428724 [DEBUG] mod_fax.c:137 FLOW T.30 Rx:  ff 13 83 00 62 f8 44
2009-08-28 11:06:06.428724 [DEBUG] mod_fax.c:137 FLOW T.30 In state 7
2009-08-28 11:06:06.428724 [DEBUG] mod_fax.c:137 FLOW T.30 Unexpected DCS received in state 7
2009-08-28 11:06:06.428724 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 7 to 3
2009-08-28 11:06:06.428724 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  DCN with final frame tag
2009-08-28 11:06:06.428724 [DEBUG] mod_fax.c:137 FLOW T.30 Tx:  ff 13 fa
2009-08-28 11:06:06.428724 [DEBUG] mod_fax.c:137 FLOW FAX Switching from V.17 + V.21 to V.21 (-14.51dBm0)
2009-08-28 11:06:06.468724 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 3
2009-08-28 11:06:06.468724 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_C_NON_ECM_RX to T30_PHASE_D_TX
2009-08-28 11:06:06.468724 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:06:06.468724 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4
2009-08-28 11:06:07.548713 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
2009-08-28 11:06:07.628704 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
2009-08-28 11:06:07.628704 [DEBUG] mod_fax.c:137 FLOW T.30 Disconnecting
2009-08-28 11:06:07.628704 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_E
2009-08-28 11:06:07.628704 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0
2009-08-28 11:06:07.628704 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 1
2009-08-28 11:06:07.628704 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 3 to 2
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_E, state 2
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:167 ==============================================================================
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:180 Fax processing not successful - result (13) Unexpected message received.
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:185 Remote station id: 
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:186 Local station id:  SpanDSP Fax Ident
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:187 Pages transferred: 0
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:189 Total fax pages:   0
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:190 Image resolution:  8031x7700
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:191 Transfer Rate:     14400
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:193 ECM status         on
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:194 remote country:   
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:195 remote vendor:    
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:196 remote model:     
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:198 ==============================================================================
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 2 to 32
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 8
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 8
2009-08-28 11:06:08.628536 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete
2009-08-28 11:06:08.648545 [DEBUG] switch_core_codec.c:122 Restore original codec.
EXECUTE sofia/external/7629 at 85.0.30.241 hangup()
2009-08-28 11:06:08.648545 [NOTICE] mod_dptools.c:633 Hangup sofia/external/7629 at 85.0.30.241 [CS_EXECUTE] [NORMAL_CLEARING]
2009-08-28 11:06:08.648545 [DEBUG] switch_channel.c:1683 Send signal sofia/external/7629 at 85.0.30.241 [KILL]
2009-08-28 11:06:08.648545 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:06:08.648545 [DEBUG] switch_core_state_machine.c:491 (sofia/external/7629 at 85.0.30.241) State EXECUTE going to sleep
2009-08-28 11:06:08.648545 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_HANGUP
2009-08-28 11:06:08.648545 [DEBUG] switch_core_state_machine.c:434 (sofia/external/7629 at 85.0.30.241) State HANGUP
2009-08-28 11:06:08.648545 [DEBUG] mod_sofia.c:338 Channel sofia/external/7629 at 85.0.30.241 hanging up, cause: NORMAL_CLEARING
2009-08-28 11:06:08.648545 [DEBUG] mod_sofia.c:396 Sending BYE to sofia/external/7629 at 85.0.30.241
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:46 sofia/external/7629 at 85.0.30.241 Standard HANGUP, cause: NORMAL_CLEARING
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:434 (sofia/external/7629 at 85.0.30.241) State HANGUP going to sleep
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:476 (sofia/external/7629 at 85.0.30.241) State Change CS_HANGUP -> CS_REPORTING
2009-08-28 11:06:08.652458 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629 at 85.0.30.241 [BREAK]
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629 at 85.0.30.241) Running State Change CS_REPORTING
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:612 (sofia/external/7629 at 85.0.30.241) State REPORTING
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:53 sofia/external/7629 at 85.0.30.241 Standard REPORTING, cause: NORMAL_CLEARING
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:612 (sofia/external/7629 at 85.0.30.241) State REPORTING going to sleep
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:411 (sofia/external/7629 at 85.0.30.241) State Change CS_REPORTING -> CS_DESTROY
2009-08-28 11:06:08.652458 [DEBUG] switch_core_session.c:1068 Session 26 (sofia/external/7629 at 85.0.30.241) Locked, Waiting on external entities
2009-08-28 11:06:08.652458 [NOTICE] switch_core_session.c:1086 Session 26 (sofia/external/7629 at 85.0.30.241) Ended
2009-08-28 11:06:08.652458 [NOTICE] switch_core_session.c:1088 Close Channel sofia/external/7629 at 85.0.30.241 [CS_DESTROY]
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629 at 85.0.30.241) State DESTROY
2009-08-28 11:06:08.652458 [DEBUG] mod_sofia.c:255 sofia/external/7629 at 85.0.30.241 SOFIA DESTROY
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:60 sofia/external/7629 at 85.0.30.241 Standard DESTROY
2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629 at 85.0.30.241) State DESTROY going to sleep

More information about the FreeSWITCH-users mailing list