[Freeswitch-users] Receiving T.38 fax - CFR not sent by FreeSWITCH after training

9 Jul 2016

      Hello!

First, I'd like to report that faxing issue from my previous mail  
("Incorrect reply to T.38 re-INVITE") is still present in FS 1.6.8. It  
doesn't bother me anymore though as I've observed that FS is issuing  
re-INVITE also with outgoing fax (I think against common recommendation)  
thus I can mitigate this problem by disabling re-INVITE from my device.

While testing FreeSWITCH 1.6.8 with one local operator I've encountered  
another issue - when receiving fax from this operator FS is not sending  
T.30 CFR message after training (i.e. I don't see it transmitted over  
ethernet) despite "Tx:  CFR with final frame tag" showing in log:

22.470661 [DEBUG] switch_core_media.c:9271 IMAGE UDPTL CHANGING DEST TO:  
[91.187.232.24:3659]
22.470661 [DEBUG] switch_core_media.c:9262 Remote address:port  
[91.187.232.24:3659] has not changed.
22.470661 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No signal is present
25.690845 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase  
A_CED, state ANSWERING
25.690845 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Starting answer mode
25.690845 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase  
A_CED to B_TX
25.690845 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0
25.690845 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 4
25.710846 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2
25.710846 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state  
ANSWERING to R
25.710846 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Sending ident 'SpanDSP  
Fax Ident'
25.710846 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  CSI without final  
frame tag
25.710846 [DEBUG] mod_spandsp_fax.c:276 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
25.710846 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 s->send_hdlc_handler,  
len = 23
27.450946 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase  
B_TX, state R
27.450946 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS:
27.450946 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Store and  
forward Internet fax (T.37): Not set
27.450946 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .1..= Real-time  
Internet fax (T.38): Set
27.450946 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= 3G mobile  
network: Not set
27.450946 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= V.8  
capabilities: Not set
27.470947 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= Preferred  
octets: 256 octets
27.470947 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Ready to  
transmit a fax document (polling): Not set
27.470947 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..1.= Can receive  
fax: Set
27.470947 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..10 11..= Supported  
data signalling rates: V.27 ter, V.29, and V.17
27.470947 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....=  
R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
27.470947 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= 2-D coding:  
Set
27.470947 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..10= Recording  
width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1%
27.470947 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 10..= Recording  
length: Unlimited
27.490948 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .111 ....= Receiver's  
minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85
27.490948 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension  
indicator: Set
27.490948 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.=  
Compressed/uncompressed mode: Compressed
27.490948 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .1..= Error  
correction mode (ECM): ECM
27.490948 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....= T.6 coding:  
Set
27.490948 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension  
indicator: Set
27.490948 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= "Field not  
valid" supported: Not set
27.510949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Multiple  
selective polling: Not set
27.510949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Polled  
sub-address: Not set
27.510949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= T.43  
coding: Not set
27.510949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...0 ....= Plane  
interleave: Not set
27.510949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Voice  
coding with 32kbit/s ADPCM (Rec. G.726): Not set
27.510949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= Reserved  
for the use of extended voice coding set: Not set
27.510949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension  
indicator: Set
27.530950 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...1=  
R8x15.4lines/mm: Set
27.530950 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.=  
300x300pels/25.4mm: Not set
27.530950 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .1..=  
R16x15.4lines/mm and/or 400x400pels/25.4mm: Set
27.530950 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 1...= Inch-based  
resolution preferred: Set
27.530950 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...1 ....=  
Metric-based resolution preferred: Set
27.530950 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Minimum  
scan line time for higher resolutions: T15.4 = T7.7
27.550951 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= Selective  
polling: Not set
27.550951 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension  
indicator: Set
27.550951 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0=  
Sub-addressing: Not set
27.550951 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Password:  
Not set
27.550951 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Ready to  
transmit a data file (polling): Not set
27.550951 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...0 ....= Binary file  
transfer (BFT): Not set
27.550951 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Document  
transfer mode (DTM): Not set
27.550951 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= Electronic  
data interchange (EDI): Not set
27.570952 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension  
indicator: Set
27.570952 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Basic  
transfer mode (BTM): Not set
27.570952 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Ready to  
transfer a character or mixed mode document (polling): Not set
27.570952 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= Character  
mode: Not set
27.570952 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Mixed mode  
(Annex E/T.4): Not set
27.570952 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension  
indicator: Set
27.590954 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Processable  
mode 26 (Rec. T.505): Not set
27.590954 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Digital  
network capability: Not set
27.590954 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Duplex  
capability: Half only
27.590954 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= JPEG  
coding: Not set
27.590954 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...0 ....= Full colour  
mode: Not set
27.590954 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= 12bits/pel  
component: Not set
27.590954 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension  
indicator: Set
27.610955 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= No  
subsampling (1:1:1): Not set
27.610955 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Custom  
illuminant: Not set
27.610955 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Custom  
gamut range: Not set
27.610955 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 1...= North  
American Letter (215.9mm x 279.4mm): Set
27.610955 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...1 ....= North  
American Legal (215.9mm x 355.6mm): Set
27.610955 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..1. ....=  
Single-progression sequential coding (Rec. T.85) basic: Set
27.610955 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....=  
Single-progression sequential coding (Rec. T.85) optional L0: Set
27.630956 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= Extension  
indicator: Not set
27.630956 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  DIS with final  
frame tag
27.630956 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  ff 13 80 04 ee fa  
c4 80 9d 80 80 80 78
27.630956 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 s->send_hdlc_handler,  
len = 13
28.110983 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase  
B_TX, state R
28.110983 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase  
B_TX, state R
28.110983 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_TX  
to B_RX
28.110983 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 4
28.110983 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 0
28.130984 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4
29.591068 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 A signal is present
29.591068 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is  
Carrier up (-2) in state R
29.611069 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is  
Framing OK (-6) in state R
29.611069 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4-flagged
31.231162 [INFO] switch_rtp.c:6669 Auto Changing audio port from  
91.187.232.24:3659 to 91.187.232.24:11894
31.711189 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Type TSI - CRC OK  
(clean)
31.711189 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T4-flagged (7200  
remaining)
31.731190 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  TSI without final  
frame tag
31.731190 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 03 43 72 65 73  
55 20 6b 6c 61 54 78 61 46 20 79 70 70 61 48 20 41
31.731190 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Remote gave TSI as: "A  
Happy FaxTalk User"
32.751249 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Type DCS - CRC OK  
(clean)
32.751249 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining)
32.771250 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  DCS with final  
frame tag
32.771250 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 13 83 00 22 f8 00
32.771250 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state R
32.771250 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DCS:
32.791251 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Store and  
forward Internet fax (T.37): Not set
32.791251 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Real-time  
Internet fax (T.38): Not set
32.791251 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= 3G mobile  
network: Not set
32.791251 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..1.= Receive  
fax: Set
32.811252 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..10 00..= Selected  
data signalling rate: V.17 14400bps
32.811252 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....=  
R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set
32.811252 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= 2-D coding:  
Not set
32.811252 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..00= Recording  
width: 215mm +- 1%
32.811252 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 10..= Recording  
length: Unlimited
32.811252 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .111 ....= Minimum  
scan line time: 0ms
32.811252 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension  
indicator: Set
32.831253 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.=  
Compressed/uncompressed mode: Compressed
32.831253 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Error  
correction mode (ECM): Non-ECM
32.831253 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= Frame size:  
256 octets
32.831253 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= T.6 coding:  
Not set
32.831253 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= Extension  
indicator: Not set
32.831253 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Far end selected  
compression T.4 1-D (2)
32.851254 [DEBUG] mod_spandsp_fax.c:317 === Negotiation Result  
=======================================================
32.851254 [DEBUG] mod_spandsp_fax.c:318 Remote station id: A Happy FaxTalk  
User
32.851254 [DEBUG] mod_spandsp_fax.c:319 Local station id:  SpanDSP Fax  
Ident
32.851254 [DEBUG] mod_spandsp_fax.c:320 Transfer Rate:     14400
32.851254 [DEBUG] mod_spandsp_fax.c:322 ECM status         off
32.851254 [DEBUG] mod_spandsp_fax.c:323 remote country:
32.851254 [DEBUG] mod_spandsp_fax.c:324 remote vendor:
32.871256 [DEBUG] mod_spandsp_fax.c:325 remote model:
32.871256 [DEBUG] mod_spandsp_fax.c:327  
==============================================================================
32.871256 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Get document with modem  
(7) V.17 at 14400bps
32.871256 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state R to  
F_TCF
32.871256 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase  
C_NON_ECM_RX
32.871256 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2
32.891257 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Receive complete in  
phase B_RX, state F_TCF
32.891257 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is  
Carrier down (-1) in state F_TCF
32.891257 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX  
to C_NON_ECM_RX
32.891257 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0
32.891257 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 7
32.911258 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 0
32.911258 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No signal is present
32.991262 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 A signal is present
34.531351 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is  
Training succeeded (-4) in state F_TCF
34.531351 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2 (42880 remaining)
35.971433 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Receive complete in  
phase C_NON_ECM_RX, state F_TCF
35.971433 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Non-ECM signal status is  
Carrier down (-1) in state F_TCF
35.971433 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Trainability (TCF) test  
result - 20832 total bits. longest run of zeros was 20832
35.971433 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase  
C_NON_ECM_RX to B_TX
35.971433 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0
35.991434 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 4
35.991434 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state  
F_TCF to F_CFR
35.991434 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 send_simple_frame(s,  
T30_CFR)
35.991434 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  CFR with final  
frame tag
35.991434 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  ff 13 84
35.991434 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 s->send_hdlc_handler,  
len = 3
35.991434 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No signal is present
37.171502 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase  
B_TX, state F_CFR
37.171502 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 shut_down_hdlc_tx(s)
37.171502 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase  
B_TX, state F_CFR
37.171502 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state  
F_CFR to F_DOC_NON_ECM
37.171502 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_TX  
to C_NON_ECM_RX
37.191503 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0
37.191503 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 7
37.191503 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 0
37.211504 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T2
[no actual CFR sent]
40.590697 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 A signal is present
42.470805 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Type TSI - CRC OK  
(clean)
42.470805 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T2 (13920 remaining)
42.470805 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  TSI without final  
frame tag
42.490806 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 03 43 72 65 73  
55 20 6b 6c 61 54 78 61 46 20 79 70 70 61 48 20 41
42.490806 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Remote gave TSI as: "A  
Happy FaxTalk User"

[TSI + DCS + training from operator repeats few times, each time no CFR  
 from FreeSWITCH after training but according to log it should be sent]

I think this might be some operator issue (it wouldn't be the single one),  
but perhaps something can be done for interoperability on FS side also as  
I can receive fax correctly from this operator using softphone with T.38  
support or gateway based on Texas Instruments fax-modem + analog fax.
So far I've built FS on Windows to get bigger picture, use debugger and  
add few extra log lines present above but I think I'll have to wait with  
testing till Monday as for unknown reason my test account from operator is  
not responding to incoming calls at the moment.

One oddity of this operator seems to be that each T.38 frame is sent only  
once - if frame would drop and there would be no next frame to send or  
there would be long pause between messages (that way no T.38 redundancy  
through secondary info in next packet would help) it might result in  
problems.

I'm looking for suggestions where to lay my eyes on for debugging.

-- 
TMSZ

[Freeswitch-users] Receiving T.38 fax - CFR not sent by FreeSWITCH after training

Tomasz Ostrowski