[Solved] 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 9 21:21:39 UTC 2016
Dear Ian,
> On 02.03.2016, at 11:45, Holger Kipp <Holger.Kipp at alogis.com> wrote:
>
>
> 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
Setting crtscts on its own did not help. I also tried an LogiLink AU0033 USB-Adapter which resulted in a comparable behaviour (sending first page only). So it is not related to uftdi.
It turned out to be an issue with the modems as well (even though their default setting _is_ hardware handshake, there seems to be a problem with xon/xoff) - maybe together with changes to tty-handling between 7.4 and 10.2.
setting crtscts -ixon -ixoff for .init
and locking these settings (=> crtscts xon xoff for .lock) (done in rc.d/serial) however did help.
Modems in question are Devolo 56k-I (ISDN). I have not checked other modems (eg ELSA ISDN TL V34) yet due to time constraints.
Maybe this information is helpful if someone else is encountering a similar problem.
Many thanks and best regards,
Holger
__________________________________________________________
Holger Kipp
Diplom-Mathematiker
Senior Consultant
Tel. : +49 30 436 58 114
Fax. : +49 30 436 58 214
Mobil: +49 178 36 58 114
Email: holger.kipp at alogis.com
alogis AG
Alt-Moabit 90b
D-10559 Berlin
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