Problems with ucom/uftdi and sendfax on 10.2 p12 (works like a charm with 7.4)
Holger Kipp
Holger.Kipp at alogis.com
Wed Mar 2 10:43:42 UTC 2016
Am 01.03.2016 um 23:08 schrieb Ian Lepore <ian at freebsd.org<mailto:ian at freebsd.org>>:
On Tue, 2016-03-01 at 19:58 +0000, Holger Kipp wrote:
Hi all,
I currently encounter a problem with sending faxes with new server
and FreeBSD 10.2-RELEASE p12
using mgetty+sendfax and RS232-Modems via USB to RS232-Adapter (com,
uftdi).
Problem is that _after_ sending the first page, the reply of modem is
not read correctly.
In Error case, Faxlog says:
02/29 18:46:10 aU4 read 64, write 64
02/29 18:46:10 aU4 read 52, write 52
02/29 18:46:10 aU4 page complete, 40900 bytes sent
02/29 18:46:10 aU4 sending DLE ','
02/29 18:46:10 aU4 got:[0a][0d][0a]OK[0d]
02/29 18:46:18 aU4 got response: 'OK'
02/29 18:46:18 aU4 fax_send_page("f2.g3") started...
02/29 18:46:18 aU4 tio_set_flow_control( HARD )
02/29 18:46:18 aU4 fax_send: 'AT+FDT'
02/29 18:46:18 aU4 fax_wait_for(CONNECT)
02/29 18:46:18 aU4 got:[0a]
02/29 18:48:18 aU4 Warning: got alarm signal!
So I run into timeout because the modem does not reply as expected
after AT+FDT-command (maybe even after sending DLE ',‘ because the OK
response seems to take some more time than under FreeBSD 7.4).
if I issue "tip modem4" (which is /dev/cuaU4), I get the missing
replies including CONNECT from the modem (then leaving tip with "~.“)
root at faxserver:/usr/local/etc/mgetty+sendfax # tip modem4
connected
AT+FDT
CONNECT
+FHS:43
OK
AT+FCLASS=0
OK
~
[EOT]
root at faxserver:/usr/local/etc/mgetty+sendfax #
This works correctly with same modems and USB to RS232-Adapter
(uftdi) under FreeBSD 7.4.
02/29 12:18:26 aU4 receiver cap.: '+FIS:1,5,0,2,1,1,0,3' -> fine 144
2D/MR ECM** found **
02/29 12:18:26 aU4 sendfax: IGNORE DCD (carrier) status
02/29 12:18:26 aU4 fax_send: 'AT+FDT'
02/29 12:18:26 aU4 fax_wait_for(CONNECT)
02/29 12:18:33 aU4 transmission par.: '+FCS:1,5,0,2,0,0,0,3'** found
**
02/29 12:18:33 aU4 sending f1.g3...
02/29 12:19:04 aU4 page complete, 34495 bytes sent
02/29 12:19:04 aU4 sending DLE ','
02/29 12:19:10 aU4 got response: 'OK'
02/29 12:19:10 aU4 fax_send: 'AT+FDT'
02/29 12:19:10 aU4 fax_wait_for(CONNECT)** found **
02/29 12:19:11 aU4 sending f2.g3...
02/29 12:19:55 aU4 page complete, 60064 bytes sent
02/29 12:19:55 aU4 sending DLE ','
02/29 12:20:01 aU4 got response: 'OK'
02/29 12:20:01 aU4 fax_send: 'AT+FDT'
02/29 12:20:01 aU4 fax_wait_for(CONNECT)** found **
02/29 12:20:01 aU4 sending f3.g3...
02/29 12:20:52 aU4 page complete, 71335 bytes sent
02/29 12:20:52 aU4 sending DLE ','
02/29 12:20:57 aU4 got response: 'OK'
02/29 12:20:57 aU4 fax_send: 'AT+FDT'
02/29 12:20:57 aU4 fax_wait_for(CONNECT)** found **
02/29 12:20:58 aU4 sending f4.g3...
02/29 12:21:40 aU4 page complete, 58628 bytes sent
02/29 12:21:40 aU4 sending DLE '.'
02/29 12:21:49 aU4 connection hangup: '+FHS:00'
02/29 12:21:49 aU4 got response: 'OK'
02/29 12:21:49 aU4 fax_send: 'AT+FCLASS=0'
This is with devolo 56k i ISDN-modems, but it looks more like a USB
interface communication issue to me.
Modems and USB-to-RS232 are the same - connected to FreeBSD 7.4
servers works (sends all pages), connected to 10.2 server does not
work (sends first page only).
I can also provide dmesg.boot details on request but didn’t want to
pollute the list.
Difference with stty -a /dev/cuaU4 seems to be clocal instead of
-clocal which I can’t set for cuaU4, only for .init and .lock. which
does not help.
7.4 Kernel comes with uftdi and ucom compiled in.
10.2 Kernel has the same issues with ucom and uftdi loaded as kernel
modules or compiled in.
mgetty+sendfax is version 1.1.35_1 on FreeBSD 7.4 and version 1.1.37
on FreeBSD 10.2-RELEASE p12.
Any other ideas where to look further or what to investigate?
Many thanks and best regards,
Holger
Seeing "tio_set_flow_control( HARD )>" in your output, along with the
fact that you said the expected output finally appeared after you
connected with tip, makes me suspect that flow control is at the root
of this problem.
The biggest ftdi driver difference before/after freebsd 8 is that the
driver used to automatically re-intialize the chip on every open to set
up some arbitrary combination of comms parameters (baud, flow control,
etc) -- I forget all the details now, I'd have to do some digging
through logs to find exactly what it used to set. Now the driver
leaves the chip alone at open time, and the contents of the
/dev/cuaU#.init and cuaU#.lock files should be completely in control of
the serial parameters.
Is it possible that you set up the .init and/or .lock devices in some
rc script in freebsd 7 and forgot about it? If not, then maybe the
driver init changes are enough to explain the glitch.
I wonder if this would fix it:
stty -f /dev/cuaU4.init crtscts
If so, then put that command into an rc script, or maybe into a devd
rule that runs whenever that usb-serial is attached.
If not... then I guess we'll figure out what to try next. :)
Dear Ian,
below you will find stty settings in old and new system.
I had tried crtscts, but without success and not properly documented.
Have tried it once more (see below), now also documented ;-)
FreeBSD 7.4:
faxserver# stty -f /dev/cuaU4
speed 9600 baud;
lflags: -echo
oflags: -oxtabs
cflags: cs8 -parenb
faxserver# stty -f /dev/cuaU4.init
speed 9600 baud;
lflags: -echo
oflags: -oxtabs
cflags: cs8 -parenb
faxserver# stty -f /dev/cuaU4.lock
speed 0 baud;
lflags: -icanon -isig -iexten -echo
iflags: -icrnl -ixon -ixany -imaxbel -brkint
oflags: -opost -onlcr -oxtabs
cflags: -cread cs5 -parenb -hupcl
discard dsusp eof eol eol2 erase erase2 intr kill
^@ ^@ ^@ ^@ ^@ ^@ ^@ ^@ ^@
lnext min quit reprint start status stop susp werase
^@ 0 ^@ ^@ ^@ ^@ ^@ ^@ ^@
FreeBSD 10.2-RELEASE
faxserver# stty -f /dev/cuaU4
speed 9600 baud;
lflags: echoe echoke echoctl
oflags: tab0
cflags: cs8 -parenb clocal
faxserver# stty -f /dev/cuaU4.init
speed 9600 baud;
lflags: echoe echoke echoctl
oflags: tab0
cflags: cs8 -parenb
faxserver# stty -f /dev/cuaU4.lock
speed 0 baud;
lflags: -icanon -isig -iexten -echo
iflags: -icrnl -ixon -ixany -imaxbel -brkint
oflags: -opost -onlcr tab0
cflags: -cread cs5 -parenb -hupcl
discard dsusp eof eol eol2 erase erase2 intr kill
^@ ^@ ^@ ^@ ^@ ^@ ^@ ^@ ^@
lnext min quit reprint start status stop susp werase
^@ 0 ^@ ^@ ^@ ^@ ^@ ^@ ^@
original settings (I have not changed anything for cuaU7):
faxserver# stty -f /dev/cuaU7
speed 9600 baud;
lflags: echoe echoke echoctl
oflags: tab0
cflags: cs8 -parenb clocal
faxserver# stty -f /dev/cuaU7.init
speed 9600 baud;
lflags: echoe echoke echoctl
oflags: tab0
cflags: cs8 -parenb
faxserver# stty -f /dev/cuaU7.lock
speed 0 baud;
lflags: -icanon -isig -iexten -echo
iflags: -icrnl -ixon -ixany -imaxbel -brkint
oflags: -opost -onlcr tab0
cflags: -cread cs5 -parenb -hupcl
discard dsusp eof eol eol2 erase erase2 intr kill
^@ ^@ ^@ ^@ ^@ ^@ ^@ ^@ ^@
lnext min quit reprint start status stop susp werase
^@ 0 ^@ ^@ ^@ ^@ ^@ ^@ ^@
I have set crtscts on 10.2 as requested:
faxserver# stty -f /dev/cuaU4.init crtscts
faxserver# stty -f /dev/cuaU4.init
speed 9600 baud;
lflags: echoe echoke echoctl
oflags: tab0
cflags: cs8 -parenb crtscts
then during transmission I get:
faxserver# stty -f /dev/cuaU4
speed 38400 baud;
lflags: -icanon -isig -iexten -echo
iflags: -icrnl -ixon -ixany -imaxbel -brkint
oflags: -opost -onlcr tab0
cflags: cs8 -parenb clocal crtscts
eol
^@
so crtscts is obviously set. I don’t know why clocal is set instead of –clocal, though (I _can_ change /dev/cuaU4 to -clocal whilst cuaU4 is in use, but that also does not help (tested separately, see my remarks at the end)).
But behavior for faxing is exactly the same with crtscts set:
03/02 10:50:34 sendfax: interim release 1.1.37-Jun05
03/02 10:50:34 sending fax to <xxxxxxxx>
03/02 10:50:34 checking f1.g3
03/02 10:50:34 checking f2.g3
03/02 10:50:34 checking f3.g3
03/02 10:50:34 checking f4.g3
03/02 10:50:34 checking f5.g3
03/02 10:50:34 aU4 tss: set speed to 38400 (113000)
03/02 10:50:34 aU4 mdm_send: 'ATV1Q0'
03/02 10:50:34 aU4 got:ATV1Q0[0d]
03/02 10:50:34 aU4 mdm_command: string 'ATV1Q0'
03/02 10:50:34 aU4 got:[0d][0a]OK[0d]
03/02 10:50:34 aU4 mdm_command: string 'OK' -> OK
03/02 10:50:34 aU4 mdm_send: 'ATI'
03/02 10:50:34 aU4 got:[0a]ATI[0d]
03/02 10:50:34 aU4 got:[0d][0a]282[0d]
03/02 10:50:34 aU4 mdm_gis: string 1: '282'
03/02 10:50:34 aU4 got:[0a][0d][0a]OK[0d]
03/02 10:50:34 aU4 mdm_identify: string '282'
03/02 10:50:34 aU4 ELSA MicroLink 28.8/56K series detected
03/02 10:50:35 aU4 mdm_send: 'ATI3'
03/02 10:50:35 aU4 got:[0a]ATI3[0d]
03/02 10:50:35 aU4 got:[0d][0a]Version 1.87 / 31.07.2000[0d]
03/02 10:50:35 aU4 mdm_gis: string 1: 'Version 1.87 / 31.07.2000'
03/02 10:50:35 aU4 got:[0a][0d][0a]OK[0d]
03/02 10:50:35 aU4 additional info: 'Version 1.87 / 31.07.2000'
03/02 10:50:35 aU4 mdm_send: 'AT+FCLASS=2.0'
03/02 10:50:35 aU4 got:[0a]AT+FCLASS=2.0[0d]
03/02 10:50:35 aU4 mdm_command: string 'AT+FCLASS=2.0'
03/02 10:50:35 aU4 got:[0d][0a]OK[0d]
03/02 10:50:35 aU4 mdm_command: string 'OK' -> OK
03/02 10:50:35 aU4 mdm_send: 'AT+FLI="+49"'
03/02 10:50:35 aU4 got:[0a]AT+FLI="+49"[0d]
03/02 10:50:35 aU4 mdm_command: string 'AT+FLI="+49"'
03/02 10:50:35 aU4 got:[0d][0a]OK[0d]
03/02 10:50:35 aU4 mdm_command: string 'OK' -> OK
03/02 10:50:35 aU4 mdm_send: 'AT+FCC=1,5,0,2,0,0,0,0'
03/02 10:50:35 aU4 got:[0a]AT+FCC=1,5,0,2,0,0,0,0[0d]
03/02 10:50:35 aU4 mdm_command: string 'AT+FCC=1,5,0,2,0,0,0,0'
03/02 10:50:35 aU4 got:[0d][0a]OK[0d]
03/02 10:50:35 aU4 mdm_command: string 'OK' -> OK
03/02 10:50:35 aU4 mdm_send: 'AT+FBO=0'
03/02 10:50:35 aU4 got:[0a]AT+FBO=0[0d]
03/02 10:50:35 aU4 mdm_command: string 'AT+FBO=0'
03/02 10:50:35 aU4 got:[0d][0a]OK[0d]
03/02 10:50:35 aU4 mdm_command: string 'OK' -> OK
03/02 10:50:35 aU4 mdm_send: 'AT+FNR=1,1,1,0'
03/02 10:50:35 aU4 got:[0a]AT+FNR=1,1,1,0[0d]
03/02 10:50:35 aU4 mdm_command: string 'AT+FNR=1,1,1,0'
03/02 10:50:35 aU4 got:[0d][0a]OK[0d]
03/02 10:50:35 aU4 mdm_command: string 'OK' -> OK
03/02 10:50:35 aU4 mdm_send: 'AT+FLO=2'
03/02 10:50:35 aU4 got:[0a]AT+FLO=2[0d]
03/02 10:50:35 aU4 mdm_command: string 'AT+FLO=2'
03/02 10:50:35 aU4 got:[0d][0a]OK[0d]
03/02 10:50:35 aU4 mdm_command: string 'OK' -> OK
03/02 10:50:35 aU4 mdm_send: 'AT&H3'
03/02 10:50:35 aU4 got:[0a]AT&H3[0d]
03/02 10:50:35 aU4 mdm_command: string 'AT&H3'
03/02 10:50:35 aU4 got:[0d][0a]ERROR[0d]
03/02 10:50:35 aU4 mdm_command: string 'ERROR' -> ERROR
03/02 10:50:35 aU4 cannot set 'modem_handshake'; ignored
03/02 10:50:35 aU4 fax_send: 'ATD0<xxxxxxxx>'
03/02 10:50:35 aU4 fax_wait_for(OK)
03/02 10:50:35 aU4 got:[0a]ATD0<xxxxxxxx>[0d]
03/02 10:50:35 aU4 fax_wait_for: string 'ATD0<xxxxxxxx>'
03/02 10:50:35 aU4 got:[0d][0a]+FCO[0d]
03/02 10:50:48 aU4 fax_wait_for: string '+FCO'
03/02 10:50:48 aU4 got:[0a][0d][0a]+FIS:1,3,2,2,0,1,0,0[0d]
03/02 10:50:49 aU4 fax_wait_for: string '+FIS:1,3,2,2,0,1,0,0'
03/02 10:50:49 aU4 receiver cap.: '+FIS:1,3,2,2,0,1,0,0' -> fine ECM
03/02 10:50:49 aU4 got:[0a][0d][0a]OK[0d]
03/02 10:50:49 aU4 fax_wait_for: string 'OK'** found **
03/02 10:50:49 aU4 sendfax: IGNORE DCD (carrier) status
03/02 10:50:49 aU4 fax_send_page("f1.g3") started...
03/02 10:50:49 aU4 tio_set_flow_control( HARD )
03/02 10:50:49 aU4 fax_send: 'AT+FDT'
03/02 10:50:49 aU4 fax_wait_for(CONNECT)
03/02 10:50:49 aU4 got:[0a]AT+FDT[0d]
03/02 10:50:49 aU4 fax_wait_for: string 'AT+FDT'
03/02 10:50:49 aU4 got:[0d][0a]+FCS:1,3,0,2,0,0,0,0[0d]
03/02 10:50:55 aU4 fax_wait_for: string '+FCS:1,3,0,2,0,0,0,0'
03/02 10:50:55 aU4 transmission par.: '+FCS:1,3,0,2,0,0,0,0'
03/02 10:50:55 aU4 got:[0a][0d][0a]CONNECT[0d]
03/02 10:50:55 aU4 fax_wait_for: string 'CONNECT'** found **
03/02 10:50:55 aU4 tio_set_flow_control( HARD XON_OUT )
03/02 10:50:55 aU4 sending f1.g3...
03/02 10:50:55 aU4 read 64, write 64
03/02 10:50:55 aU4 read 64, write 64
03/02 10:50:55 aU4 read 64, write 64
[..]
03/02 10:51:26 aU4 read 64, write 64
03/02 10:51:26 aU4 read 64, write 64
03/02 10:51:26 aU4 read 52, write 52
03/02 10:51:26 aU4 page complete, 40900 bytes sent
03/02 10:51:26 aU4 sending DLE ','
03/02 10:51:26 aU4 got:[0a][0d][0a]OK[0d]
03/02 10:51:33 aU4 got response: 'OK'
03/02 10:51:33 aU4 fax_send_page("f2.g3") started...
03/02 10:51:33 aU4 tio_set_flow_control( HARD )
03/02 10:51:33 aU4 fax_send: 'AT+FDT'
03/02 10:51:33 aU4 fax_wait_for(CONNECT)
03/02 10:51:33 aU4 got:[0a]
03/02 10:53:34 aU4 Warning: got alarm signal!
03/02 10:53:34 aU4 mdm_read_byte: read returned -1: Interrupted system call
03/02 10:53:34 aU4 mdm_get_line: cannot read byte, return: Interrupted system call
03/02 10:53:34 aU4 AT+FDT -> some error (-6), abort fax send!
I could change the AT&H3 to devolo-specific AT+IFC=2,2 (which is RTS,CTS) - had already tested that just to make sure, but that is modem default setting anyway so makes no difference. I reverted to default sendfax.config afterwards (identical to the 7.4 settings).
I noticed that for the first page I have HARD XON_OUT and for the second page only HARD. This is however exactly the same behavior on 7.4.
stty -f /dev/cuaU4 reflects this (-ixon is set when trying to send the second page, and even if -clocal was set before (during transmission of the first page), this is then set back to clocal when the second page starts).
On both 7.4 and 10.2 file /etc/rc.d/serial is unchanged, so no special settings are applied.
No special settings for devd.conf either. And 10.2 (apart from added ports) is just the plain RELEASE installation.
Originally this was a binary installation only (apart from added ports). I have installed usr/src (10.2-RELEASE p12) and compiled with ucom, uftdi in kernel (because it was compiled in in 7.4 FreeBSD version) to rule out any possible side effects there. Nothing changed, but at least I’m now prepared to recompile with any patches thrown at me ;-)
Otherwise I’m a bit out of ideas right now.
Many thanks and best regards,
Holger
Diplom-Mathematiker
Holger Kipp
Senior Consultant [cid:alogis_footer4d30.png]
Fon: +49 30 436 58 114
Fax: +49 30 436 58 214
Mobil: +49 178 36 58 114
alogis AG
Alt-Moabit 90 B
10559 Berlin
holger.kipp at alogis.com www.alogis.com<http://www.alogis.com/>
alogis AG
Sitz/Registergericht: Berlin/AG Charlottenburg, HRB 71484
Vorstand: Arne Friedrichs, Joern Samuelson
Aufsichtsratsvorsitzender: Reinhard Mielke
More information about the freebsd-stable
mailing list