2009-08-28 11:04:05.852705 [NOTICE] switch_channel.c:602 New Channel sofia/external/7629@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@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@85.0.30.241) State NEW 2009-08-28 11:04:05.852705 [DEBUG] sofia.c:3289 Channel sofia/external/7629@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@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@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@85.0.30.241 [BREAK] 2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629@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@85.0.30.241) State INIT 2009-08-28 11:04:05.856715 [DEBUG] mod_sofia.c:83 sofia/external/7629@85.0.30.241 SOFIA INIT 2009-08-28 11:04:05.856715 [DEBUG] mod_sofia.c:111 (sofia/external/7629@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@85.0.30.241 [BREAK] 2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:481 (sofia/external/7629@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@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@85.0.30.241) State ROUTING 2009-08-28 11:04:05.856715 [DEBUG] mod_sofia.c:130 sofia/external/7629@85.0.30.241 SOFIA ROUTING 2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:78 sofia/external/7629@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@85.0.30.241 parsing [public->unloop] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 parsing [public->outside_call] continue=true Dialplan: sofia/external/7629@85.0.30.241 Absolute Condition [outside_call] Dialplan: sofia/external/7629@85.0.30.241 Action set(outside_call=true) Dialplan: sofia/external/7629@85.0.30.241 parsing [public->call_debug] continue=true Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/7629@85.0.30.241 parsing [public->public_extensions] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [public_extensions] destination_number(9998) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 parsing [public->vmain] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [vmain] destination_number(9998) =~ /^(9999)$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 parsing [public->fax2mail] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (PASS) [fax2mail] destination_number(9998) =~ /^(9998)$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 Action set(fax_verbose=true) Dialplan: sofia/external/7629@85.0.30.241 Action set(fax_disable_v17=false) Dialplan: sofia/external/7629@85.0.30.241 Action set(fax_use_ecm=true) Dialplan: sofia/external/7629@85.0.30.241 Action answer() Dialplan: sofia/external/7629@85.0.30.241 Action playback(silence_stream://2000) Dialplan: sofia/external/7629@85.0.30.241 Action rxfax(/tmp/${uuid}.rxfax.tiff) Dialplan: sofia/external/7629@85.0.30.241 Action hangup() 2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:114 (sofia/external/7629@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@85.0.30.241 [BREAK] 2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:484 (sofia/external/7629@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@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@85.0.30.241) State EXECUTE 2009-08-28 11:04:05.856715 [DEBUG] mod_sofia.c:173 sofia/external/7629@85.0.30.241 SOFIA EXECUTE 2009-08-28 11:04:05.856715 [DEBUG] switch_core_state_machine.c:151 sofia/external/7629@85.0.30.241 Standard EXECUTE EXECUTE sofia/external/7629@85.0.30.241 set(outside_call=true) 2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [outside_call]=[true] EXECUTE sofia/external/7629@85.0.30.241 set(fax_verbose=true) 2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [fax_verbose]=[true] EXECUTE sofia/external/7629@85.0.30.241 set(fax_disable_v17=false) 2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [fax_disable_v17]=[false] EXECUTE sofia/external/7629@85.0.30.241 set(fax_use_ecm=true) 2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [fax_use_ecm]=[true] EXECUTE sofia/external/7629@85.0.30.241 answer() 2009-08-28 11:04:05.856715 [DEBUG] mod_dptools.c:649 sofia/external/7629@85.0.30.241 receive message [ANSWER] 2009-08-28 11:04:05.856715 [DEBUG] sofia_glue.c:2263 AUDIO RTP [sofia/external/7629@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@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@85.0.30.241 [BREAK] 2009-08-28 11:04:05.860708 [NOTICE] mod_dptools.c:649 Channel [sofia/external/7629@85.0.30.241] has been answered 2009-08-28 11:04:05.860708 [DEBUG] switch_channel.c:182 sofia/external/7629@85.0.30.241 receive message [AUDIO_SYNC] EXECUTE sofia/external/7629@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@8000hz 1 channels 20ms 2009-08-28 11:04:05.860708 [DEBUG] switch_core_io.c:649 sofia/external/7629@85.0.30.241 receive message [TRANSCODING_NECESSARY] 2009-08-28 11:04:05.860708 [DEBUG] sofia.c:3289 Channel sofia/external/7629@85.0.30.241 entering state [completed][200] 2009-08-28 11:04:05.872721 [DEBUG] sofia.c:3289 Channel sofia/external/7629@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@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@85.0.30.241 receive message [AUDIO_SYNC] 2009-08-28 11:04:07.908721 [DEBUG] switch_core_io.c:232 sofia/external/7629@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@85.0.30.241 hangup() 2009-08-28 11:04:31.148726 [NOTICE] mod_dptools.c:633 Hangup sofia/external/7629@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@85.0.30.241 [KILL] 2009-08-28 11:04:31.148726 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629@85.0.30.241 [BREAK] 2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:491 (sofia/external/7629@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@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@85.0.30.241) State HANGUP 2009-08-28 11:04:31.148726 [DEBUG] mod_sofia.c:338 Channel sofia/external/7629@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@85.0.30.241 2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:46 sofia/external/7629@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@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@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@85.0.30.241 [BREAK] 2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629@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@85.0.30.241) State REPORTING 2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:53 sofia/external/7629@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@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@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@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@85.0.30.241) Ended 2009-08-28 11:04:31.148726 [NOTICE] switch_core_session.c:1088 Close Channel sofia/external/7629@85.0.30.241 [CS_DESTROY] 2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629@85.0.30.241) State DESTROY 2009-08-28 11:04:31.148726 [DEBUG] mod_sofia.c:255 sofia/external/7629@85.0.30.241 SOFIA DESTROY 2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:60 sofia/external/7629@85.0.30.241 Standard DESTROY 2009-08-28 11:04:31.148726 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629@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@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@85.0.30.241) Running State Change CS_NEW 2009-08-28 11:04:57.372710 [DEBUG] sofia.c:3289 Channel sofia/external/7629@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@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@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@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@85.0.30.241 [BREAK] 2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629@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@85.0.30.241) State INIT 2009-08-28 11:04:57.376739 [DEBUG] mod_sofia.c:83 sofia/external/7629@85.0.30.241 SOFIA INIT 2009-08-28 11:04:57.376739 [DEBUG] mod_sofia.c:111 (sofia/external/7629@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@85.0.30.241 [BREAK] 2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:481 (sofia/external/7629@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@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@85.0.30.241) State ROUTING 2009-08-28 11:04:57.376739 [DEBUG] mod_sofia.c:130 sofia/external/7629@85.0.30.241 SOFIA ROUTING 2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:78 sofia/external/7629@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@85.0.30.241 parsing [public->unloop] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 parsing [public->outside_call] continue=true Dialplan: sofia/external/7629@85.0.30.241 Absolute Condition [outside_call] Dialplan: sofia/external/7629@85.0.30.241 Action set(outside_call=true) Dialplan: sofia/external/7629@85.0.30.241 parsing [public->call_debug] continue=true Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/7629@85.0.30.241 parsing [public->public_extensions] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [public_extensions] destination_number(9998) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 parsing [public->vmain] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [vmain] destination_number(9998) =~ /^(9999)$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 parsing [public->fax2mail] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (PASS) [fax2mail] destination_number(9998) =~ /^(9998)$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 Action set(fax_verbose=true) Dialplan: sofia/external/7629@85.0.30.241 Action set(fax_disable_v17=false) Dialplan: sofia/external/7629@85.0.30.241 Action set(fax_use_ecm=true) Dialplan: sofia/external/7629@85.0.30.241 Action answer() Dialplan: sofia/external/7629@85.0.30.241 Action playback(silence_stream://2000) Dialplan: sofia/external/7629@85.0.30.241 Action rxfax(/tmp/${uuid}.rxfax.tiff) Dialplan: sofia/external/7629@85.0.30.241 Action hangup() 2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:114 (sofia/external/7629@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@85.0.30.241 [BREAK] 2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:484 (sofia/external/7629@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@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@85.0.30.241) State EXECUTE 2009-08-28 11:04:57.376739 [DEBUG] mod_sofia.c:173 sofia/external/7629@85.0.30.241 SOFIA EXECUTE 2009-08-28 11:04:57.376739 [DEBUG] switch_core_state_machine.c:151 sofia/external/7629@85.0.30.241 Standard EXECUTE EXECUTE sofia/external/7629@85.0.30.241 set(outside_call=true) 2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [outside_call]=[true] EXECUTE sofia/external/7629@85.0.30.241 set(fax_verbose=true) 2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [fax_verbose]=[true] EXECUTE sofia/external/7629@85.0.30.241 set(fax_disable_v17=false) 2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [fax_disable_v17]=[false] EXECUTE sofia/external/7629@85.0.30.241 set(fax_use_ecm=true) 2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [fax_use_ecm]=[true] EXECUTE sofia/external/7629@85.0.30.241 answer() 2009-08-28 11:04:57.376739 [DEBUG] mod_dptools.c:649 sofia/external/7629@85.0.30.241 receive message [ANSWER] 2009-08-28 11:04:57.376739 [DEBUG] sofia_glue.c:2263 AUDIO RTP [sofia/external/7629@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@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@85.0.30.241 [BREAK] 2009-08-28 11:04:57.380744 [NOTICE] mod_dptools.c:649 Channel [sofia/external/7629@85.0.30.241] has been answered 2009-08-28 11:04:57.380744 [DEBUG] switch_channel.c:182 sofia/external/7629@85.0.30.241 receive message [AUDIO_SYNC] 2009-08-28 11:04:57.380744 [DEBUG] sofia.c:3289 Channel sofia/external/7629@85.0.30.241 entering state [completed][200] EXECUTE sofia/external/7629@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@8000hz 1 channels 20ms 2009-08-28 11:04:57.380744 [DEBUG] switch_core_io.c:649 sofia/external/7629@85.0.30.241 receive message [TRANSCODING_NECESSARY] 2009-08-28 11:04:57.388729 [DEBUG] sofia.c:3289 Channel sofia/external/7629@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@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@85.0.30.241 receive message [AUDIO_SYNC] 2009-08-28 11:04:59.428463 [DEBUG] switch_core_io.c:232 sofia/external/7629@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@85.0.30.241 hangup() 2009-08-28 11:05:22.648728 [NOTICE] mod_dptools.c:633 Hangup sofia/external/7629@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@85.0.30.241 [KILL] 2009-08-28 11:05:22.648728 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629@85.0.30.241 [BREAK] 2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:491 (sofia/external/7629@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@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@85.0.30.241) State HANGUP 2009-08-28 11:05:22.648728 [DEBUG] mod_sofia.c:338 Channel sofia/external/7629@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@85.0.30.241 2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:46 sofia/external/7629@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@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@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@85.0.30.241 [BREAK] 2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629@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@85.0.30.241) State REPORTING 2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:53 sofia/external/7629@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@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@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@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@85.0.30.241) Ended 2009-08-28 11:05:22.648728 [NOTICE] switch_core_session.c:1088 Close Channel sofia/external/7629@85.0.30.241 [CS_DESTROY] 2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629@85.0.30.241) State DESTROY 2009-08-28 11:05:22.648728 [DEBUG] mod_sofia.c:255 sofia/external/7629@85.0.30.241 SOFIA DESTROY 2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:60 sofia/external/7629@85.0.30.241 Standard DESTROY 2009-08-28 11:05:22.648728 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629@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@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@85.0.30.241) Running State Change CS_NEW 2009-08-28 11:05:48.912723 [DEBUG] sofia.c:3289 Channel sofia/external/7629@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@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@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@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@85.0.30.241 [BREAK] 2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629@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@85.0.30.241) State INIT 2009-08-28 11:05:48.916860 [DEBUG] mod_sofia.c:83 sofia/external/7629@85.0.30.241 SOFIA INIT 2009-08-28 11:05:48.916860 [DEBUG] mod_sofia.c:111 (sofia/external/7629@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@85.0.30.241 [BREAK] 2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:481 (sofia/external/7629@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@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@85.0.30.241) State ROUTING 2009-08-28 11:05:48.916860 [DEBUG] mod_sofia.c:130 sofia/external/7629@85.0.30.241 SOFIA ROUTING 2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:78 sofia/external/7629@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@85.0.30.241 parsing [public->unloop] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 parsing [public->outside_call] continue=true Dialplan: sofia/external/7629@85.0.30.241 Absolute Condition [outside_call] Dialplan: sofia/external/7629@85.0.30.241 Action set(outside_call=true) Dialplan: sofia/external/7629@85.0.30.241 parsing [public->call_debug] continue=true Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/7629@85.0.30.241 parsing [public->public_extensions] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [public_extensions] destination_number(9998) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 parsing [public->vmain] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (FAIL) [vmain] destination_number(9998) =~ /^(9999)$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 parsing [public->fax2mail] continue=false Dialplan: sofia/external/7629@85.0.30.241 Regex (PASS) [fax2mail] destination_number(9998) =~ /^(9998)$/ break=on-false Dialplan: sofia/external/7629@85.0.30.241 Action set(fax_verbose=true) Dialplan: sofia/external/7629@85.0.30.241 Action set(fax_disable_v17=false) Dialplan: sofia/external/7629@85.0.30.241 Action set(fax_use_ecm=true) Dialplan: sofia/external/7629@85.0.30.241 Action answer() Dialplan: sofia/external/7629@85.0.30.241 Action playback(silence_stream://2000) Dialplan: sofia/external/7629@85.0.30.241 Action rxfax(/tmp/${uuid}.rxfax.tiff) Dialplan: sofia/external/7629@85.0.30.241 Action hangup() 2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:114 (sofia/external/7629@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@85.0.30.241 [BREAK] 2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:484 (sofia/external/7629@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@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@85.0.30.241) State EXECUTE 2009-08-28 11:05:48.916860 [DEBUG] mod_sofia.c:173 sofia/external/7629@85.0.30.241 SOFIA EXECUTE 2009-08-28 11:05:48.916860 [DEBUG] switch_core_state_machine.c:151 sofia/external/7629@85.0.30.241 Standard EXECUTE EXECUTE sofia/external/7629@85.0.30.241 set(outside_call=true) 2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [outside_call]=[true] EXECUTE sofia/external/7629@85.0.30.241 set(fax_verbose=true) 2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [fax_verbose]=[true] EXECUTE sofia/external/7629@85.0.30.241 set(fax_disable_v17=false) 2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [fax_disable_v17]=[false] EXECUTE sofia/external/7629@85.0.30.241 set(fax_use_ecm=true) 2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:748 sofia/external/7629@85.0.30.241 SET [fax_use_ecm]=[true] EXECUTE sofia/external/7629@85.0.30.241 answer() 2009-08-28 11:05:48.916860 [DEBUG] mod_dptools.c:649 sofia/external/7629@85.0.30.241 receive message [ANSWER] 2009-08-28 11:05:48.916860 [DEBUG] sofia_glue.c:2263 AUDIO RTP [sofia/external/7629@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@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@85.0.30.241 [BREAK] 2009-08-28 11:05:48.920709 [NOTICE] mod_dptools.c:649 Channel [sofia/external/7629@85.0.30.241] has been answered 2009-08-28 11:05:48.920709 [DEBUG] switch_channel.c:182 sofia/external/7629@85.0.30.241 receive message [AUDIO_SYNC] 2009-08-28 11:05:48.920709 [DEBUG] sofia.c:3289 Channel sofia/external/7629@85.0.30.241 entering state [completed][200] EXECUTE sofia/external/7629@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@8000hz 1 channels 20ms 2009-08-28 11:05:48.920709 [DEBUG] switch_core_io.c:649 sofia/external/7629@85.0.30.241 receive message [TRANSCODING_NECESSARY] 2009-08-28 11:05:48.928705 [DEBUG] sofia.c:3289 Channel sofia/external/7629@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@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@85.0.30.241 receive message [AUDIO_SYNC] 2009-08-28 11:05:50.968739 [DEBUG] switch_core_io.c:232 sofia/external/7629@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@85.0.30.241 hangup() 2009-08-28 11:06:08.648545 [NOTICE] mod_dptools.c:633 Hangup sofia/external/7629@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@85.0.30.241 [KILL] 2009-08-28 11:06:08.648545 [DEBUG] switch_core_session.c:932 Send signal sofia/external/7629@85.0.30.241 [BREAK] 2009-08-28 11:06:08.648545 [DEBUG] switch_core_state_machine.c:491 (sofia/external/7629@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@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@85.0.30.241) State HANGUP 2009-08-28 11:06:08.648545 [DEBUG] mod_sofia.c:338 Channel sofia/external/7629@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@85.0.30.241 2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:46 sofia/external/7629@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@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@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@85.0.30.241 [BREAK] 2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:398 (sofia/external/7629@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@85.0.30.241) State REPORTING 2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:53 sofia/external/7629@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@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@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@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@85.0.30.241) Ended 2009-08-28 11:06:08.652458 [NOTICE] switch_core_session.c:1088 Close Channel sofia/external/7629@85.0.30.241 [CS_DESTROY] 2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629@85.0.30.241) State DESTROY 2009-08-28 11:06:08.652458 [DEBUG] mod_sofia.c:255 sofia/external/7629@85.0.30.241 SOFIA DESTROY 2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:60 sofia/external/7629@85.0.30.241 Standard DESTROY 2009-08-28 11:06:08.652458 [DEBUG] switch_core_state_machine.c:564 (sofia/external/7629@85.0.30.241) State DESTROY going to sleep