Date: Thu, 10 Mar 2016 12:10:48 -0700 From: Ian Lepore <ian@freebsd.org> To: Holger Kipp <Holger.Kipp@alogis.com> Cc: "freebsd-stable@freebsd.org" <freebsd-stable@freebsd.org> Subject: Re: [Solved] Problems with ucom/uftdi and sendfax on 10.2 p12 (works like a charm with 7.4) Message-ID: <1457637048.1406.72.camel@freebsd.org> In-Reply-To: <7D2BDA5F-889D-4234-8F64-6D00956E05E3@alogis.com> References: <C2938AE5-8766-4F3B-AB2A-CA35B64391DC@alogis.com> <1456865414.13785.119.camel@freebsd.org> , <9CA439E9-66BD-488D-AC8D-E0FCACC48A15@alogis.com> <7D2BDA5F-889D-4234-8F64-6D00956E05E3@alogis.com>
next in thread | previous in thread | raw e-mail | index | archive | help
On Wed, 2016-03-09 at 21:21 +0000, Holger Kipp wrote:
> 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@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@faxserver:/usr/local/etc/mgetty+sendfax # tip modem4
> > connected
> > AT+FDT
> > CONNECT
> >
> > +FHS:43
> >
> > OK
> > AT+FCLASS=0
> > 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=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
>
I'm glad to hear you got it working. I spent some time looking at the
driver code last weekend and couldn't spot any changes between 7.x and
10.x that would make a difference. I did see in the debug output from
your fax software it was setting both rtscts and xonxoff flow control
at the same time "tio_set_flow_control( HARD XON_OUT )", and the ftdi
driver doesn't really handle that (I suspect many drivers don't). But
I didn't have time to do any experiments to see what effect that has on
real hardware.
-- Ian
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?1457637048.1406.72.camel>