From owner-freebsd-stable@freebsd.org Thu Mar 10 19:10:58 2016 Return-Path: Delivered-To: freebsd-stable@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id ECB6DACA1A1 for ; Thu, 10 Mar 2016 19:10:57 +0000 (UTC) (envelope-from ian@freebsd.org) Received: from outbound1b.ore.mailhop.org (outbound1b.ore.mailhop.org [54.200.247.200]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id CD677FA7 for ; Thu, 10 Mar 2016 19:10:57 +0000 (UTC) (envelope-from ian@freebsd.org) X-MHO-User: e8d6d9db-e6f3-11e5-8dfb-c75234cc769e X-Report-Abuse-To: https://support.duocircle.com/support/solutions/articles/5000540958-duocircle-standard-smtp-abuse-information X-Originating-IP: 73.34.117.227 X-Mail-Handler: DuoCircle Outbound SMTP Received: from ilsoft.org (unknown [73.34.117.227]) by outbound1.ore.mailhop.org (Halon Mail Gateway) with ESMTPSA; Thu, 10 Mar 2016 19:11:35 +0000 (UTC) Received: from rev (rev [172.22.42.240]) by ilsoft.org (8.15.2/8.14.9) with ESMTP id u2AJAmHj010469; Thu, 10 Mar 2016 12:10:48 -0700 (MST) (envelope-from ian@freebsd.org) Message-ID: <1457637048.1406.72.camel@freebsd.org> Subject: Re: [Solved] Problems with ucom/uftdi and sendfax on 10.2 p12 (works like a charm with 7.4) From: Ian Lepore To: Holger Kipp Cc: "freebsd-stable@freebsd.org" Date: Thu, 10 Mar 2016 12:10:48 -0700 In-Reply-To: <7D2BDA5F-889D-4234-8F64-6D00956E05E3@alogis.com> References: <1456865414.13785.119.camel@freebsd.org> , <9CA439E9-66BD-488D-AC8D-E0FCACC48A15@alogis.com> <7D2BDA5F-889D-4234-8F64-6D00956E05E3@alogis.com> Content-Type: text/plain; charset="windows-1251" X-Mailer: Evolution 3.16.5 FreeBSD GNOME Team Port Mime-Version: 1.0 Content-Transfer-Encoding: 8bit X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 10 Mar 2016 19:10:58 -0000 On Wed, 2016-03-09 at 21:21 +0000, Holger Kipp wrote: > Dear Ian, > > > On 02.03.2016, at 11:45, Holger Kipp > > wrote: > > > > > > Am 01.03.2016 um 23:08 schrieb Ian Lepore > 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 > > 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' > > 03/02 10:50:35 aU4 fax_wait_for(OK) > > 03/02 10:50:35 aU4 got:[0a]ATD0[0d] > > 03/02 10:50:35 aU4 fax_wait_for: string 'ATD0' > > 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