El día jueves, enero 03, 2019 a las 01:36:08p. m. +0100, Ludovic Rousseau escribió:
> I hope this email will go to freebsd-usb@ since I am not a member of this
> list.
>
> Le jeu. 3 janv. 2019 à 13:19, Hans Petter Selasky <h...@selasky.org> a écrit :
> >
> > 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.
>
> You can enable pcscd hotplug debug by editing DEBUG_HOTPLUG at
> https://salsa.debian.org/rousseau/PCSC/blob/master/src/hotplug_libusb.c#L69
>
> 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, self
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 sectors)
Jan 4 07:49:43 c720-r342378 kernel: WARNING: WITNESS option enabled, expect
reduced performance.
Jan 4 07:49:43 c720-r342378 kernel: Trying to mount root from ufs:/dev/ada0p2
[rw,noatime]...
Jan 4 07:49:43 c720-r342378 kernel: wlan0: Ethernet address: 90:48:9a:92:9e: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='org.freedesktop.ColorManager' (using servicehelper)
Jan 4 07:49:48 c720-r342378 dbus[882]: [system] Successfully activated service
'org.freedesktop.ColorManager'
4. Login as root and then I started as root 'tcpdump -o usbconfig.tr -d
usbconfig 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:
...
176.947374653 close(3) = 0 (0x0)
176.947633175 openat(AT_FDCWD,"/dev/ugen0.1",O_RDWR,00) = 3 (0x3)
176.947831569 openat(AT_FDCWD,"/dev/ugen0.1",O_RDWR,00) = 4 (0x4)
176.947933598 ioctl(4,USB_GET_PLUGTIME,0x7fffffffe9ac) = 0 (0x0)
...
176.950045979 close(3) = 0 (0x0)
201.816756320 openat(AT_FDCWD,"/dev/ugen1.1",O_RDWR,00) = 3 (0x3)
216.766758812 openat(AT_FDCWD,"/dev/ugen1.1",O_RDWR,00) = 4 (0x4)
221.728691723 ioctl(4,USB_GET_PLUGTIME,0x7fffffffe9ac) = 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=0 md=HOST spd=HIGH (480Mbps)
pwr=SAVE (0mA)
ugen0.1: <0x8086 XHCI root HUB> at usbus0, cfg=0 md=HOST spd=SUPER (5.0Gbps)
pwr=SAVE (0mA)
ugen0.2: <SunplusIT Inc HD WebCam> at usbus0, cfg=0 md=HOST spd=HIGH (480Mbps)
pwr=ON (500mA)
ugen1.2: <vendor 0x8087 product 0x8000> at usbus1, cfg=0 md=HOST spd=HIGH
(480Mbps) pwr=SAVE (0mA)
ugen0.3: <vendor 0x0489 product 0xe056> at usbus0, cfg=0 md=HOST spd=FULL
(12Mbps) pwr=ON (100mA)
ugen0.4: <HID Global OMNIKEY 6121 Smart Card Reader> at usbus0, cfg=0 md=HOST
spd=FULL (12Mbps)
pwr=ON (100mA)
Any comments on this ugen1.X?
matthias
--
Matthias Apitz, ✉ g...@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.
signature.asc
Description: PGP signature
