Date: Fri, 4 Jan 2019 09:02:27 +0100 From: Matthias Apitz <guru@unixarea.de> To: Ludovic Rousseau <ludovic.rousseau@gmail.com> Cc: Hans Petter Selasky <hps@selasky.org>, freebsd-usb@freebsd.org Subject: Re: r342378: usbconfig takes 3-5 minutes to read the bus Message-ID: <20190104080227.GB2604@c720-r342378> In-Reply-To: <CAGstE8B6RxBqBG9uqUXc60JcsB6=-QcmN1Q4kTgbgwoWGVaNyA@mail.gmail.com> References: <20190102154701.GA13702@c720-r342378> <2f013cf9-b073-04fd-9932-079f86fa24b1@selasky.org> <d0f569af-342f-dac8-8f6d-4fc0ff21924e@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> <CAGstE8B6RxBqBG9uqUXc60JcsB6=-QcmN1Q4kTgbgwoWGVaNyA@mail.gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
--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 <hps@selasky.org> =
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: <SunplusIT Inc HD WebCam> at =
usbus0
Jan 4 07:49:43 c720-r342378 kernel: ugen1.2: <vendor 0x8087 product 0x8000=
> at usbus1
Jan 4 07:49:43 c720-r342378 kernel: uhub2 on uhub1
Jan 4 07:49:43 c720-r342378 kernel: uhub2: <vendor 0x8087 product 0x8000, =
class 9/0, rev 2.00/0.04, addr 2> on usbus1
Jan 4 07:49:43 c720-r342378 kernel: ugen0.3: <vendor 0x0489 product 0xe056=
> 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: <Identiv uTrust 3512 SAM slot=
Token> 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: <TS256GMTS400 N1126I> 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: <Intel EHCI root HUB> 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: <SunplusIT Inc HD WebCam> at usbus0, cfg=3D0 md=3DHOST spd=3DHIGH =
(480Mbps) pwr=3DON (500mA)
ugen1.2: <vendor 0x8087 product 0x8000> at usbus1, cfg=3D0 md=3DHOST spd=3D=
HIGH (480Mbps) pwr=3DSAVE (0mA)
ugen0.3: <vendor 0x0489 product 0xe056> at usbus0, cfg=3D0 md=3DHOST spd=3D=
FULL (12Mbps) pwr=3DON (100mA)
ugen0.4: <HID Global OMNIKEY 6121 Smart Card Reader> 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--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20190104080227.GB2604>