From owner-freebsd-usb@freebsd.org Fri Jan 4 08:02:38 2019 Return-Path: Delivered-To: freebsd-usb@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 6367D141FA1D for ; Fri, 4 Jan 2019 08:02:38 +0000 (UTC) (envelope-from guru@unixarea.de) Received: from ms-10.1blu.de (ms-10.1blu.de [178.254.4.101]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 169E685F15 for ; Fri, 4 Jan 2019 08:02:36 +0000 (UTC) (envelope-from guru@unixarea.de) Received: from [82.113.121.248] (helo=localhost.unixarea.de) by ms-10.1blu.de with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.86_2) (envelope-from ) id 1gfKR6-0001GH-N0; Fri, 04 Jan 2019 09:02:33 +0100 Received: from localhost.my.domain (localhost [127.0.0.1]) by localhost.unixarea.de (8.15.2/8.14.9) with ESMTPS id x0482TNX002884 (version=TLSv1.3 cipher=TLS_AES_256_GCM_SHA384 bits=256 verify=NO); Fri, 4 Jan 2019 09:02:29 +0100 (CET) (envelope-from guru@unixarea.de) Received: (from guru@localhost) by localhost.my.domain (8.15.2/8.14.9/Submit) id x0482RZh002883; Fri, 4 Jan 2019 09:02:27 +0100 (CET) (envelope-from guru@unixarea.de) X-Authentication-Warning: localhost.my.domain: guru set sender to guru@unixarea.de using -f Date: Fri, 4 Jan 2019 09:02:27 +0100 From: Matthias Apitz To: Ludovic Rousseau Cc: Hans Petter Selasky , freebsd-usb@freebsd.org Subject: Re: r342378: usbconfig takes 3-5 minutes to read the bus Message-ID: <20190104080227.GB2604@c720-r342378> Reply-To: Matthias Apitz Mail-Followup-To: Ludovic Rousseau , Hans Petter Selasky , freebsd-usb@freebsd.org References: <20190102154701.GA13702@c720-r342378> <2f013cf9-b073-04fd-9932-079f86fa24b1@selasky.org> <20190103060431.GA2711@c720-r342378> <5950d771-ffa9-9325-b102-295fd092052e@selasky.org> <20190103094850.GA2595@c720-r342378> <076e01a2-51e7-b140-28c9-1c58d034327b@selasky.org> <20190103113512.GA2547@c720-r342378> <34dfc02b-b252-9f38-a905-31a713012c6a@selasky.org> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="iFRdW5/EC4oqxDHL" Content-Disposition: inline In-Reply-To: X-Operating-System: FreeBSD 13.0-CURRENT r342378 (amd64) X-message-flag: Mails containing HTML will not be read! Please send only plain text. User-Agent: Mutt/1.11.1 (2018-12-01) X-Con-Id: 51246 X-Con-U: 0-guru X-Originating-IP: 82.113.121.248 X-Rspamd-Queue-Id: 169E685F15 X-Spamd-Bar: ------- Authentication-Results: mx1.freebsd.org X-Spamd-Result: default: False [-7.04 / 15.00]; RCVD_VIA_SMTP_AUTH(0.00)[]; HAS_REPLYTO(0.00)[guru@unixarea.de]; HAS_XOIP(0.00)[]; TO_DN_SOME(0.00)[]; IP_SCORE(-3.36)[ip: (-9.10), ipnet: 178.254.0.0/19(-4.28), asn: 42730(-3.43), country: DE(-0.01)]; HAS_ATTACHMENT(0.00)[]; HAS_XAW(0.00)[]; RCVD_COUNT_THREE(0.00)[4]; MX_GOOD(-0.01)[cached: mail.unixarea.de]; NEURAL_HAM_SHORT(-0.97)[-0.968,0]; SIGNED_PGP(-2.00)[]; FREEMAIL_TO(0.00)[gmail.com]; RECEIVED_SPAMHAUS_PBL(0.00)[248.121.113.82.zen.spamhaus.org : 127.0.0.11]; FROM_EQ_ENVFROM(0.00)[]; R_DKIM_NA(0.00)[]; RCVD_IN_DNSWL_LOW(-0.10)[101.4.254.178.list.dnswl.org : 127.0.5.1]; ASN(0.00)[asn:42730, ipnet:178.254.0.0/19, country:DE]; MIME_UNKNOWN(0.10)[application/x-troff]; ARC_NA(0.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-1.000,0]; REPLYTO_EQ_FROM(0.00)[]; FROM_HAS_DN(0.00)[]; RCPT_COUNT_THREE(0.00)[3]; NEURAL_HAM_LONG(-1.00)[-1.000,0]; TAGGED_RCPT(0.00)[]; MIME_TRACE(0.00)[0:+,1:+,2:+,3:~]; DMARC_NA(0.00)[unixarea.de]; MIME_GOOD(-0.20)[multipart/signed,multipart/mixed,text/plain]; AUTH_NA(1.00)[]; TO_MATCH_ENVRCPT_SOME(0.00)[]; R_SPF_NA(0.00)[]; MID_RHS_NOT_FQDN(0.50)[]; RCVD_TLS_LAST(0.00)[] X-Content-Filtered-By: Mailman/MimeDel 2.1.29 X-BeenThere: freebsd-usb@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: FreeBSD support for USB List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 04 Jan 2019 08:02:38 -0000 --iFRdW5/EC4oqxDHL Content-Type: multipart/mixed; boundary="KFztAG8eRSV9hGtP" Content-Disposition: inline --KFztAG8eRSV9hGtP Content-Type: text/plain; charset=utf-8 Content-Disposition: inline Content-Transfer-Encoding: quoted-printable El d=C3=ADa jueves, enero 03, 2019 a las 01:36:08p. m. +0100, Ludovic Rouss= eau escribi=C3=B3: > I hope this email will go to freebsd-usb@ since I am not a member of this= list. >=20 > Le jeu. 3 janv. 2019 =C3=A0 13:19, Hans Petter Selasky = a =C3=A9crit : > > > > On 1/3/19 12:35 PM, Matthias Apitz wrote: > > > but is doing so 3000++ times: > > > > > > $ dmesg | grep 'PID 544' | wc -l > > > 3441 > > > > > > This proc is started by devd(8) with that devd(8) hook: > > > > > > > Hi, > > > > Basically pcscd is congesting the enumeration SX lock, preventing > > usbconfig from running because it tries to open the same USB device over > > and over again. I'm not sure why, but it can have something to do with > > how you start pcscd. > > > > Can you try to use the example rules given by the pcscd packet message? > > > > attach 100 { > > device-name "ugen[0-9]+"; > > action "/usr/local/sbin/pcscd -H"; > > }; > > > > detach 100 { > > device-name "ugen[0-9]+"; > > action "/usr/local/sbin/pcscd -H"; > > }; Btw: for the above devd(8) hooks one must also start /usr/local/sbin/pcscd as a service via /usr/local/etc/rc.d/pcscd > > Maybe there is a bug in pcsd that it tries to open the same USB device > > over and over again if there is an libusb error? Maybe it should sleep a > > bit before trying to re-enumerate devices? > > > > I'm CC'ing Ludovic Rousseau, in case he has any comments. >=20 > You can enable pcscd hotplug debug by editing DEBUG_HOTPLUG at > https://salsa.debian.org/rousseau/PCSC/blob/master/src/hotplug_libusb.c#L= 69 >=20 > A pcscd trace would be helpful. See https://pcsclite.apdu.fr/#support Hello Ludovic and Hans, First of all, thanks for your helping hands! I will later come back to the debugging of pcscd itself. But before that we should solve the problem outside of pcscd. I did today morning: 1. power-off 2. insert the uTrust token 3. power-on boot *without* any devd(8) or service start of pcscd here are the last boot messages in /var/log/messages: Jan 4 07:49:43 c720-r342378 kernel: uhub0: 13 ports with 13 removable, sel= f powered Jan 4 07:49:43 c720-r342378 kernel: uhub1: 2 ports with 2 removable, self = powered Jan 4 07:49:43 c720-r342378 kernel: ugen0.2: at = usbus0 Jan 4 07:49:43 c720-r342378 kernel: ugen1.2: at usbus1 Jan 4 07:49:43 c720-r342378 kernel: uhub2 on uhub1 Jan 4 07:49:43 c720-r342378 kernel: uhub2: on usbus1 Jan 4 07:49:43 c720-r342378 kernel: ugen0.3: at usbus0 Jan 4 07:49:43 c720-r342378 kernel: uhub2: 8 ports with 8 removable, self = powered Jan 4 07:49:43 c720-r342378 kernel: ugen0.4: at usbus0 Jan 4 07:49:43 c720-r342378 kernel: ada0 at ahcich0 bus 0 scbus0 target 0 = lun 0 Jan 4 07:49:43 c720-r342378 kernel: ada0: ACS-2 ATA = SATA 3.x device Jan 4 07:49:43 c720-r342378 kernel: ada0: Serial Number C196530955 Jan 4 07:49:43 c720-r342378 kernel: ada0: 600.000MB/s transfers (SATA 3.x,= UDMA6, PIO 1024bytes) Jan 4 07:49:43 c720-r342378 kernel: ada0: Command Queueing enabled Jan 4 07:49:43 c720-r342378 kernel: ada0: 244198MB (500118192 512 byte sec= tors) Jan 4 07:49:43 c720-r342378 kernel: WARNING: WITNESS option enabled, expec= t reduced performance. Jan 4 07:49:43 c720-r342378 kernel: Trying to mount root from ufs:/dev/ada= 0p2 [rw,noatime]... Jan 4 07:49:43 c720-r342378 kernel: wlan0: Ethernet address: 90:48:9a:92:9= e:43 Jan 4 07:49:43 c720-r342378 kernel: lo0: link state changed to UP Jan 4 07:49:43 c720-r342378 kernel: . Jan 4 07:49:48 c720-r342378 dbus[882]: [system] Activating service name=3D= 'org.freedesktop.ColorManager' (using servicehelper) Jan 4 07:49:48 c720-r342378 dbus[882]: [system] Successfully activated ser= vice 'org.freedesktop.ColorManager' 4. Login as root and then I started as root 'tcpdump -o usbconfig.tr -d usb= config list' resulting lines in messages: Jan 4 07:53:04 c720-r342378 login[989]: ROOT LOGIN (root) ON ttyv1 Jan 4 07:53:51 c720-r342378 kernel: USB opened by PID 1005 usbconfig Jan 4 07:53:51 c720-r342378 syslogd: last message repeated 1 times Jan 4 07:54:38 c720-r342378 kernel: USB opened by PID 1019 usbconfig Jan 4 07:55:01 c720-r342378 syslogd: last message repeated 3 times Jan 4 07:56:50 c720-r342378 syslogd: last message repeated 4 times And the trace file usbconfig.tr is attached. Please see the timestamps in each line. The printed time is when the syscall ended(!) and a close look shows: =2E.. 176.947374653 close(3) =3D 0 (0x0) 176.947633175 openat(AT_FDCWD,"/dev/ugen0.1",O_RDWR,00) =3D 3 (0x3) 176.947831569 openat(AT_FDCWD,"/dev/ugen0.1",O_RDWR,00) =3D 4 (0x4) 176.947933598 ioctl(4,USB_GET_PLUGTIME,0x7fffffffe9ac) =3D 0 (0x0) =2E.. 176.950045979 close(3) =3D 0 (0x0) 201.816756320 openat(AT_FDCWD,"/dev/ugen1.1",O_RDWR,00) =3D 3 (0x3) 216.766758812 openat(AT_FDCWD,"/dev/ugen1.1",O_RDWR,00) =3D 4 (0x4) 221.728691723 ioctl(4,USB_GET_PLUGTIME,0x7fffffffe9ac) =3D 0 (0x0) i.e. all openat(2) and ioctl(2) calls for /dev/ugen0.X devices are normal, while the calls for /dev/ugen1.X devices are delayed. We definitely should resolve this before anything else. The output of the 'usbconfig list' was: # usbconfig list ugen1.1: at usbus1, cfg=3D0 md=3DHOST spd=3DHIGH (480= Mbps) pwr=3DSAVE (0mA) ugen0.1: <0x8086 XHCI root HUB> at usbus0, cfg=3D0 md=3DHOST spd=3DSUPER (5= =2E0Gbps) pwr=3DSAVE (0mA) ugen0.2: at usbus0, cfg=3D0 md=3DHOST spd=3DHIGH = (480Mbps) pwr=3DON (500mA) ugen1.2: at usbus1, cfg=3D0 md=3DHOST spd=3D= HIGH (480Mbps) pwr=3DSAVE (0mA) ugen0.3: at usbus0, cfg=3D0 md=3DHOST spd=3D= FULL (12Mbps) pwr=3DON (100mA) ugen0.4: at usbus0, cfg=3D0 md= =3DHOST spd=3DFULL (12Mbps) pwr=3DON (100mA) Any comments on this ugen1.X? matthias --=20 Matthias Apitz, =E2=9C=89 guru@unixarea.de, http://www.unixarea.de/ +49-176= -38902045 Public GnuPG key: http://www.unixarea.de/key.pub October, 7 -- The GDR was different: Peace instead of Bundeswehr and wars, = Druschba instead of Nazis, to live instead of to survive. --KFztAG8eRSV9hGtP-- --iFRdW5/EC4oqxDHL Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQIzBAABCAAdFiEEXmn7rBYYViyzy/vBR8z35Hb+nREFAlwvExAACgkQR8z35Hb+ nRGReQ//UF6/eb32Q/ULkVAE0FD/2hJZvaxG8OoEiiiM7K33eHULxXcqaBhYldGu 4MEA3ea1n0LXfCMotWTQLjpLrB0n+XsAh6a0l/eH3RTYe93dKNR5yuJRUlr6bLmL GgtEc5R7TVoPz/0dxiwwFmqjAw2+R7p5jtqy0jnel534r71rXfKAT0PQAw8xlbz2 gFOpiX7JoFq8Oh1/IYJKklIp0kVmozSTtOkuurhsDoLbGDltfbFYriTbdtAOD9ce OQICCpWIcO6t4nsugT5FywHkNQcMnLJaveLqvaLMeCVPoAQdvC8wQ9comV3soq1D K8zq9wmiD7eYlJRPhKteslfOlOGSb873WrVyKWUxSmaAEf93BtoNFE3GZG3Rft2o aGhqppPVXe/XqEgzLWd0LB521aE6Rw8Pefc0FZO9jrDSKGX3Zaal6FwW4vx97FzJ MNMfbggpSppLu/ENNq6cIaOKI65zSovviKjBvcfTE9FNNyaeR6JB/CeXLqKD0Tde 8L9EtBc/72esmBpgRW5l2DVpmwFsE/pvtv7YJfCVDl20Zf9XsWaGWobvL8gSeakQ 4WJTLGahoXV2uti1j9sFeQIUidEzswpT4EKTH5a2d8aKGT1pRVYg7X/25MCuJCfm 0zoAOSXlJfatVXITjQSwl/ZUu8LbFD/gxaaqQRwWQ9HfekrRqhk= =WMdk -----END PGP SIGNATURE----- --iFRdW5/EC4oqxDHL--