Date: Wed, 9 Mar 2016 21:21:22 +0000 From: Holger Kipp <Holger.Kipp@alogis.com> To: Ian Lepore <ian@freebsd.org> Cc: "freebsd-stable@freebsd.org" <freebsd-stable@freebsd.org> Subject: [Solved] Problems with ucom/uftdi and sendfax on 10.2 p12 (works like a charm with 7.4) Message-ID: <7D2BDA5F-889D-4234-8F64-6D00956E05E3@alogis.com> In-Reply-To: <9CA439E9-66BD-488D-AC8D-E0FCACC48A15@alogis.com> References: <C2938AE5-8766-4F3B-AB2A-CA35B64391DC@alogis.com> <1456865414.13785.119.camel@freebsd.org>, <9CA439E9-66BD-488D-AC8D-E0FCACC48A15@alogis.com>
next in thread | previous in thread | raw e-mail | index | archive | help
Dear Ian,
> On 02.03.2016, at 11:45, Holger Kipp <Holger.Kipp@alogis.com> wrote:
>
>
> Am 01.03.2016 um 23:08 schrieb Ian Lepore <ian@freebsd.org<mailto:ian@fre=
ebsd.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 ',=91 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 "~.=93)
>
> root@faxserver:/usr/local/etc/mgetty+sendfax # tip modem4
> connected
> AT+FDT
> CONNECT
>
> +FHS:43
>
> OK
> AT+FCLASS=3D0
> OK
> ~
> [EOT]
> root@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=3D0'
>
> 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=92t want to
> pollute the list.
>
> Difference with stty -a /dev/cuaU4 seems to be clocal instead of
> -clocal which I can=92t 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=92t know why clocal is set instead of =
=96clocal, 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=3D2.0'
> 03/02 10:50:35 aU4 got:[0a]AT+FCLASS=3D2.0[0d]
> 03/02 10:50:35 aU4 mdm_command: string 'AT+FCLASS=3D2.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=3D"+49"'
> 03/02 10:50:35 aU4 got:[0a]AT+FLI=3D"+49"[0d]
> 03/02 10:50:35 aU4 mdm_command: string 'AT+FLI=3D"+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=3D1,5,0,2,0,0,0,0'
> 03/02 10:50:35 aU4 got:[0a]AT+FCC=3D1,5,0,2,0,0,0,0[0d]
> 03/02 10:50:35 aU4 mdm_command: string 'AT+FCC=3D1,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=3D0'
> 03/02 10:50:35 aU4 got:[0a]AT+FBO=3D0[0d]
> 03/02 10:50:35 aU4 mdm_command: string 'AT+FBO=3D0'
> 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=3D1,1,1,0'
> 03/02 10:50:35 aU4 got:[0a]AT+FNR=3D1,1,1,0[0d]
> 03/02 10:50:35 aU4 mdm_command: string 'AT+FNR=3D1,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=3D2'
> 03/02 10:50:35 aU4 got:[0a]AT+FLO=3D2[0d]
> 03/02 10:50:35 aU4 mdm_command: string 'AT+FLO=3D2'
> 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 c=
all
> 03/02 10:53:34 aU4 mdm_get_line: cannot read byte, return: Interrupted s=
ystem 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=3D2,2 (which is RTS,CT=
S) - had already tested that just to make sure, but that is modem default s=
etting 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 se=
cond page, and even if -clocal was set before (during transmission of the f=
irst 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 se=
ttings are applied.
> No special settings for devd.conf either. And 10.2 (apart from added port=
s) 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 i=
n kernel (because it was compiled in in 7.4 FreeBSD version) to rule out an=
y possible side effects there. Nothing changed, but at least I=92m now prep=
ared to recompile with any patches thrown at me ;-)
>
> Otherwise I=92m 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 US=
B-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 def=
ault 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 (=3D> 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@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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?7D2BDA5F-889D-4234-8F64-6D00956E05E3>