In my attempts to receive a fax from a PSTN fax machine, the transaction fails with error code 13 "Unexpected message received". Verbose logging is on for mod_fax. Here is an exerpt: ################################################# 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: CFR with final frame tag 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 13 84 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 In state 12 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Unexpected CFR received in state 12 ...... ======================================================================== ====== 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:180 Fax processing not successful - result (13) Unexpected message received. 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:185 Remote station id: ********** 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:186 Local station id: SpanDSP Fax Ident 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:187 Pages transferred: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:189 Total fax pages: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:190 Image resolution: 8031x3850 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:191 Transfer Rate: 14400 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:193 ECM status on 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:194 remote country: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:195 remote vendor: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:196 remote model: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:198 ======================================================================== ====== ################################################# I have successfully received a fax from faxzero.com on this installation, as have I successfully sent a fax from freeswitch to the PSTN fax machine in question. I've been digging, but there doesn't seem to be a whole lot of information on faxing. I guess I could use a bit of direction. Any input is much appreciated. Thanks! -- Travis
On 09/17/2009 12:08 AM, Travis Stutsman wrote:
In my attempts to receive a fax from a PSTN fax machine, the transaction fails with error code 13 "Unexpected message received". Verbose logging is on for mod_fax. Here is an exerpt:
################################################# 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: CFR with final frame tag 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 13 84 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 In state 12 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Unexpected CFR received in state 12 ...... ======================================================================== ====== 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:180 Fax processing not successful - result (13) Unexpected message received. 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:185 Remote station id: ********** 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:186 Local station id: SpanDSP Fax Ident 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:187 Pages transferred: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:189 Total fax pages: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:190 Image resolution: 8031x3850 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:191 Transfer Rate: 14400 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:193 ECM status on 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:194 remote country: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:195 remote vendor: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:196 remote model: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:198 ======================================================================== ====== #################################################
I have successfully received a fax from faxzero.com on this installation, as have I successfully sent a fax from freeswitch to the PSTN fax machine in question.
I've been digging, but there doesn't seem to be a whole lot of information on faxing. I guess I could use a bit of direction. Any input is much appreciated.
You seem to have chopped out all the interesting parts of that log. A full log might say something interesting. Steve
And make sure verbose is set to true in ./conf/autoload_configs/ fax.conf.xml. On Sep 16, 2009, at 11:50 AM, Steve Underwood wrote:
On 09/17/2009 12:08 AM, Travis Stutsman wrote:
In my attempts to receive a fax from a PSTN fax machine, the transaction fails with error code 13 "Unexpected message received". Verbose logging is on for mod_fax. Here is an exerpt:
################################################# 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: CFR with final frame tag 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 13 84 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 In state 12 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Unexpected CFR received in state 12 ...... = = = ===================================================================== ====== 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:180 Fax processing not successful - result (13) Unexpected message received. 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:185 Remote station id: ********** 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:186 Local station id: SpanDSP Fax Ident 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:187 Pages transferred: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:189 Total fax pages: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:190 Image resolution: 8031x3850 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:191 Transfer Rate: 14400 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:193 ECM status on 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:194 remote country: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:195 remote vendor: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:196 remote model: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:198 = = = ===================================================================== ====== #################################################
I have successfully received a fax from faxzero.com on this installation, as have I successfully sent a fax from freeswitch to the PSTN fax machine in question.
I've been digging, but there doesn't seem to be a whole lot of information on faxing. I guess I could use a bit of direction. Any input is much appreciated.
You seem to have chopped out all the interesting parts of that log. A full log might say something interesting.
Steve
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Alrighty. Here is mod_fax from beginning to end. ################################################# 2009-09-15 10:41:26.433382 [DEBUG] mod_fax.c:591 Raw read codec activation Success L16 20000 2009-09-15 10:41:26.433382 [DEBUG] mod_fax.c:607 Raw write codec activation Success L16 2009-09-15 10:41:26.433382 [DEBUG] switch_channel.c:182 sofia/external/**********@**.***.**.*** receive message [AUDIO_SYNC] 2009-09-15 10:41:26.464633 [DEBUG] switch_core_io.c:232 sofia/external/**********@**.***.**.*** receive message [TRANSCODING_NECESSARY] 2009-09-15 10:41:27.589676 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1 2009-09-15 10:41:27.761558 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 1 2009-09-15 10:41:27.792809 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1 2009-09-15 10:41:27.870937 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:28.308454 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:28.355331 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:28.370956 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:28.824099 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:29.27231 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:29.261615 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_A_CED, state 1 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Starting answer mode 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_A_CED to T30_PHASE_B_TX 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 1 to 17 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Sending ident 'SpanDSP Fax Ident' 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: CSI without final frame tag 2009-09-15 10:41:29.511625 [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-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 DIS: 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= 3G mobile network: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= V.8 capabilities: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Preferred octets: 256 octets 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..1.= Can receive fax: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= 2-D coding: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1% 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 10..= Recording length: Unlimited 2009-09-15 10:41:31.89811 [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-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .1.. ....= T.6 coding: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= "Field not valid" supported: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Multiple selective polling: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Polled sub-address: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= T.43 coding: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...0 ....= Plane interleave: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...1= R8x15.4lines/mm: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= Inch-based resolution preferred: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...1 ....= Metric-based resolution preferred: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Selective polling: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Sub-addressing: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Password: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Ready to transmit a data file (polling): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Ready to transfer a character or mixed mode document (polling): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= Character mode: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Digital network capability: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Duplex capability: Half only 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= JPEG coding: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...0 ....= Full colour mode: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= 12bits/pel component: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= No subsampling (1:1:1): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Custom illuminant: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Custom gamut range: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 1...= North American Letter (215.9mm x 279.4mm): Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...1 ....= North American Legal (215.9mm x 355.6mm): Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 0... ....= Extension indicator: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: DIS with final frame tag 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: ff 13 80 00 ee fa c4 80 95 80 80 80 18 2009-09-15 10:41:31.542953 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_B_RX 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 4 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4 2009-09-15 10:41:31.652332 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17 2009-09-15 10:41:32.152351 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17 2009-09-15 10:41:32.261731 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17 2009-09-15 10:41:32.402361 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 17 2009-09-15 10:41:32.402361 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4A 2009-09-15 10:41:34.11798 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T4A (11200 remaining) 2009-09-15 10:41:34.11798 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: TSI without final frame tag 2009-09-15 10:41:34.11798 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 03 43 38 37 34 31 32 36 38 34 37 35 31 20 20 20 20 20 20 20 20 20 2009-09-15 10:41:34.11798 [DEBUG] mod_fax.c:137 FLOW T.30 Remote gave TSI as: "***********" 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Stop none (0 remaining) 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: DCS with final frame tag 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 13 83 00 22 f8 44 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 In state 17 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 DCS: 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= 3G mobile network: Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..1.= Receive fax: Set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 ..10 00..= Selected data signalling rate: V.17 14400bps 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 0... ....= 2-D coding: Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..00= Recording width: 215mm +- 1% 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... 10..= Recording length: Unlimited 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .111 ....= Minimum scan line time: 0ms 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= Frame size: 256 octets 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .1.. ....= T.6 coding: Set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 0... ....= Extension indicator: Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Selected compression 3 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Get document at 14400bps, modem 7 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 17 to 7 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_C_NON_ECM_RX 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 7 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0 2009-09-15 10:41:34.402438 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7 2009-09-15 10:41:34.402438 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7 2009-09-15 10:41:34.574319 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7 2009-09-15 10:41:34.605571 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7 2009-09-15 10:41:34.605571 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7 2009-09-15 10:41:34.621196 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7 2009-09-15 10:41:34.621196 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7 2009-09-15 10:41:34.730575 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state 7 2009-09-15 10:41:35.246220 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7 2009-09-15 10:41:36.27500 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training succeeded (-4) in state 7 2009-09-15 10:41:36.27500 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T2 (42080 remaining) 2009-09-15 10:41:36.27500 [DEBUG] mod_fax.c:137 FLOW FAX Switching from V.17 + V.21 to V.17 (-16.66dBm0) 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Trainability (TCF) test result - 21822 total bits. longest run of zeros was 21600 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_C_NON_ECM_RX to T30_PHASE_B_TX 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 7 to 8 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: CFR with final frame tag 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: ff 13 84 2009-09-15 10:41:38.652601 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 8 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 8 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 8 to 12 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_C_ECM_RX 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 7 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2 2009-09-15 10:41:38.746355 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 12 2009-09-15 10:41:38.793231 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Training failed (-5) in state 12 2009-09-15 10:41:38.871359 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 12 2009-09-15 10:41:38.871359 [DEBUG] mod_fax.c:137 FLOW T.30 Start T1A 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T1A (277280 remaining) 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: CFR with final frame tag 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 13 84 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 In state 12 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Unexpected CFR received in state 12 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 12 to 3 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: DCN with final frame tag 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: ff 13 fa 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW FAX Switching from V.17 + V.21 to V.21 (-33.64dBm0) 2009-09-15 10:41:39.261999 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 3 2009-09-15 10:41:39.261999 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_C_ECM_RX to T30_PHASE_D_TX 2009-09-15 10:41:39.261999 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:39.261999 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4 2009-09-15 10:41:40.324540 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW T.30 Disconnecting 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_E 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 1 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 3 to 2 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_E, state 2 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:167 ======================================================================== ====== 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:180 Fax processing not successful - result (13) Unexpected message received. 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:185 Remote station id: *********** 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:186 Local station id: SpanDSP Fax Ident 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:187 Pages transferred: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:189 Total fax pages: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:190 Image resolution: 8031x3850 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:191 Transfer Rate: 14400 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:193 ECM status on 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:194 remote country: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:195 remote vendor: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:196 remote model: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:198 ======================================================================== ====== 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 2 to 32 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 8 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 8 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete 2009-09-15 10:41:41.433958 [DEBUG] switch_core_codec.c:122 Restore original codec. ################################################# CFR in phase C? Hmm... Thanks again. -- Travis -----Original Message----- From: freeswitch-users-bounces@lists.freeswitch.org [mailto:freeswitch-users-bounces@lists.freeswitch.org] On Behalf Of Steve Underwood Sent: Wednesday, September 16, 2009 12:51 PM To: freeswitch-users@lists.freeswitch.org Subject: Re: [Freeswitch-users] faxrx error 13 Unexpected message received On 09/17/2009 12:08 AM, Travis Stutsman wrote:
In my attempts to receive a fax from a PSTN fax machine, the transaction fails with error code 13 "Unexpected message received". Verbose logging is on for mod_fax. Here is an exerpt:
################################################# 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: CFR with final frame tag 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 13 84 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 In state 12 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Unexpected CFR received in state 12 ......
========================================================================
====== 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:180 Fax processing not successful - result (13) Unexpected message received. 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:185 Remote station id: ********** 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:186 Local station id: SpanDSP Fax Ident 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:187 Pages transferred: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:189 Total fax pages: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:190 Image resolution: 8031x3850 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:191 Transfer Rate: 14400 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:193 ECM status on 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:194 remote country: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:195 remote vendor: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:196 remote model: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:198
========================================================================
====== #################################################
I have successfully received a fax from faxzero.com on this installation, as have I successfully sent a fax from freeswitch to the PSTN fax machine in question.
I've been digging, but there doesn't seem to be a whole lot of information on faxing. I guess I could use a bit of direction. Any input is much appreciated.
You seem to have chopped out all the interesting parts of that log. A full log might say something interesting. Steve _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Hi Travis, That's a pretty weird call. It looks like you have a long delayed echo. See below. On 09/17/2009 01:21 AM, Travis Stutsman wrote:
Alrighty. Here is mod_fax from beginning to end.
################################################# 2009-09-15 10:41:26.433382 [DEBUG] mod_fax.c:591 Raw read codec activation Success L16 20000 2009-09-15 10:41:26.433382 [DEBUG] mod_fax.c:607 Raw write codec activation Success L16 2009-09-15 10:41:26.433382 [DEBUG] switch_channel.c:182 sofia/external/**********@**.***.**.*** receive message [AUDIO_SYNC] 2009-09-15 10:41:26.464633 [DEBUG] switch_core_io.c:232 sofia/external/**********@**.***.**.*** receive message [TRANSCODING_NECESSARY] 2009-09-15 10:41:27.589676 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1 2009-09-15 10:41:27.761558 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 1 2009-09-15 10:41:27.792809 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1 2009-09-15 10:41:27.870937 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:28.308454 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:28.355331 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:28.370956 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:28.824099 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:29.27231 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:29.261615 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 1 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_A_CED, state 1 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Starting answer mode 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_A_CED to T30_PHASE_B_TX 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 1 to 17 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Sending ident 'SpanDSP Fax Ident' 2009-09-15 10:41:29.511625 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: CSI without final frame tag 2009-09-15 10:41:29.511625 [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-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 DIS: 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= 3G mobile network: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= V.8 capabilities: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Preferred octets: 256 octets 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..1.= Can receive fax: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= 2-D coding: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1% 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 10..= Recording length: Unlimited 2009-09-15 10:41:31.89811 [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-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .1.. ....= T.6 coding: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= "Field not valid" supported: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Multiple selective polling: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Polled sub-address: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= T.43 coding: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...0 ....= Plane interleave: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...1= R8x15.4lines/mm: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= Inch-based resolution preferred: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...1 ....= Metric-based resolution preferred: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Selective polling: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Sub-addressing: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Password: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Ready to transmit a data file (polling): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Ready to transfer a character or mixed mode document (polling): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= Character mode: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Digital network capability: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Duplex capability: Half only 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= JPEG coding: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...0 ....= Full colour mode: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= 12bits/pel component: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= No subsampling (1:1:1): Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Custom illuminant: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Custom gamut range: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .... 1...= North American Letter (215.9mm x 279.4mm): Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ...1 ....= North American Legal (215.9mm x 355.6mm): Set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 0... ....= Extension indicator: Not set 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: DIS with final frame tag 2009-09-15 10:41:31.89811 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: ff 13 80 00 ee fa c4 80 95 80 80 80 18 2009-09-15 10:41:31.542953 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 17 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_B_RX 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 4 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0 2009-09-15 10:41:31.621081 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4 2009-09-15 10:41:31.652332 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17 2009-09-15 10:41:32.152351 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17 2009-09-15 10:41:32.261731 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17 2009-09-15 10:41:32.402361 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 17 2009-09-15 10:41:32.402361 [DEBUG] mod_fax.c:137 FLOW T.30 Start T4A 2009-09-15 10:41:34.11798 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T4A (11200 remaining) 2009-09-15 10:41:34.11798 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: TSI without final frame tag 2009-09-15 10:41:34.11798 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 03 43 38 37 34 31 32 36 38 34 37 35 31 20 20 20 20 20 20 20 20 20 2009-09-15 10:41:34.11798 [DEBUG] mod_fax.c:137 FLOW T.30 Remote gave TSI as: "***********" 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Stop none (0 remaining) 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: DCS with final frame tag 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 13 83 00 22 f8 44 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 In state 17 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 DCS: 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= 3G mobile network: Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..1.= Receive fax: Set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 ..10 00..= Selected data signalling rate: V.17 14400bps 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 0... ....= 2-D coding: Not set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..00= Recording width: 215mm +- 1% 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... 10..= Recording length: Unlimited 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .111 ....= Minimum scan line time: 0ms 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 1... ....= Extension indicator: Set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... .1..= Error correction mode (ECM): ECM 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .... 0...= Frame size: 256 octets 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 .1.. ....= T.6 coding: Set 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 0... ....= Extension indicator: Not set
They want to send us a FAX in ECM mode at 14,400bps.
2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Selected compression 3 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Get document at 14400bps, modem 7 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 17 to 7 2009-09-15 10:41:34.293059 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_C_NON_ECM_RX 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 7 2009-09-15 10:41:34.371187 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0 2009-09-15 10:41:34.402438 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7 2009-09-15 10:41:34.402438 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7 2009-09-15 10:41:34.574319 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training failed (-5) in state 7 2009-09-15 10:41:34.605571 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7 2009-09-15 10:41:34.605571 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 7 2009-09-15 10:41:34.621196 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier up (-2) in state 7 2009-09-15 10:41:34.621196 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 7 2009-09-15 10:41:34.730575 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training in progress (-3) in state 7 2009-09-15 10:41:35.246220 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Abort (-8) in state 7 2009-09-15 10:41:36.27500 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Training succeeded (-4) in state 7 2009-09-15 10:41:36.27500 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T2 (42080 remaining) 2009-09-15 10:41:36.27500 [DEBUG] mod_fax.c:137 FLOW FAX Switching from V.17 + V.21 to V.17 (-16.66dBm0) 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Non-ECM signal status is Carrier down (-1) in state 7 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Trainability (TCF) test result - 21822 total bits. longest run of zeros was 21600
They've sent us perfectly good training test data (TCF)
2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_C_NON_ECM_RX to T30_PHASE_B_TX 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 7 to 8 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: CFR with final frame tag 2009-09-15 10:41:37.574435 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: ff 13 84 2009-09-15 10:41:38.652601 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 8
We have sent the confirmation that the training test went OK
2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 8 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 8 to 12 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_C_ECM_RX 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 7 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 0 2009-09-15 10:41:38.730729 [DEBUG] mod_fax.c:137 FLOW T.30 Start T2 2009-09-15 10:41:38.746355 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier up (-2) in state 12 2009-09-15 10:41:38.793231 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Training failed (-5) in state 12 2009-09-15 10:41:38.871359 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Framing OK (-6) in state 12 2009-09-15 10:41:38.871359 [DEBUG] mod_fax.c:137 FLOW T.30 Start T1A 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Stop T1A (277280 remaining) 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: CFR with final frame tag 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Rx: ff 13 84
About one second later we have received a training confirmation message. Presumably that is an echo of the one we sent. The echo delay must have been quite big, though, or we would not have interpreted that echo as a received message.
2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 In state 12 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Unexpected CFR received in state 12 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 12 to 3 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: DCN with final frame tag 2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW T.30 Tx: ff 13 fa
Having received a message that is out of sequence, we just disconnect.
2009-09-15 10:41:39.215123 [DEBUG] mod_fax.c:137 FLOW FAX Switching from V.17 + V.21 to V.21 (-33.64dBm0) 2009-09-15 10:41:39.261999 [DEBUG] mod_fax.c:137 FLOW T.30 HDLC signal status is Carrier down (-1) in state 3 2009-09-15 10:41:39.261999 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_C_ECM_RX to T30_PHASE_D_TX 2009-09-15 10:41:39.261999 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:39.261999 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 4 2009-09-15 10:41:40.324540 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW T.30 Disconnecting 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_E 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 0 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 1 2009-09-15 10:41:40.402668 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 3 to 2 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW T.30 Send complete in phase T30_PHASE_E, state 2 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:167 ======================================================================== ====== 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:180 Fax processing not successful - result (13) Unexpected message received. 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:185 Remote station id: *********** 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:186 Local station id: SpanDSP Fax Ident 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:187 Pages transferred: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:189 Total fax pages: 0 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:190 Image resolution: 8031x3850 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:191 Transfer Rate: 14400 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:193 ECM status on 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:194 remote country: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:195 remote vendor: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:196 remote model: 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:198 ======================================================================== ====== 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from state 2 to 32 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW FAX Set rx type 8 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW FAX Set tx type 8 2009-09-15 10:41:41.402707 [DEBUG] mod_fax.c:137 FLOW FAX FAX exchange complete 2009-09-15 10:41:41.433958 [DEBUG] switch_core_codec.c:122 Restore original codec. #################################################
What kind of path was this call over? Steve
Thanks Steve. More tests today. Consistent results. The Fax machine is in the same building as the FS server. It goes out over the PSTN to my carrier, then carrier to me over IP to the server. I need to try more fax machines and more locations. -- Travis
participants (3)
-
Rob Forman
-
Steve Underwood
-
Travis Stutsman