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