[Freeswitch-users] faxrx error 13 Unexpected message received

Wed Sep 16 16:51:09 PDT 2009

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