[Freeswitch-users] Receiving T.38 fax - CFR not sent by FreeSWITCH after training
Tomasz Ostrowski
tomasz.o.ostrowski at gmail.com
Sat Jul 9 21:11:12 MSD 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
Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users
mailing list