r342378: usbconfig takes 3-5 minutes to read the bus

[Hans Petter Selasky]

On 1/2/19 11:48 AM, Matthias Apitz wrote:
> El día miércoles, enero 02, 2019 a las 09:44:06a. m. +0100, Hans Petter Selasky escribió:
> 
>> On 1/1/19 2:51 PM, Matthias Apitz wrote:
>>> Now with r342378, it works only after boot but not after withdraw/re-insert
>>> anymore. To separate the problem from GnuPG and it's software stack, I have here some
>>> small tests with usbconfig(8). First usbconfig reads fine the bus, but then
>>> it takes 3-5 minutes to get any results, see below.
>>
>> Did you update the user-space libusb aswell?
> 
> I did a complete 'make installworld' and they look updated:
> 
> $ ls -l /usr/lib/libusb*
> -r--r--r--  1 root  wheel  573256 31 dic.  12:19 /usr/lib/libusb_p.a
> -r--r--r--  1 root  wheel  541506 31 dic.  12:19 /usr/lib/libusb.a
> lrwxr-xr-x  1 root  wheel      11 31 dic.  12:33 /usr/lib/libusb.so -> libusb.so.3
> -r--r--r--  1 root  wheel   98016 31 dic.  12:33 /usr/lib/libusb.so.3
> -r--r--r--  1 root  wheel   73910 31 dic.  12:19 /usr/lib/libusbhid_p.a
> -r--r--r--  1 root  wheel   71390 31 dic.  12:19 /usr/lib/libusbhid.a
> lrwxr-xr-x  1 root  wheel      14 31 dic.  12:33 /usr/lib/libusbhid.so -> libusbhid.so.4
> -r--r--r--  1 root  wheel   23720 31 dic.  12:33 /usr/lib/libusbhid.so.4
> 
> At boot time a process is launched by devd(8) which reads the OpenPGP
> card and this works fine and has the device open:
> 
> $ ps ax | grep pcs
>   501 v0- S     0:00,22 /usr/local/sbin/pcscd --debug --foreground
> 
> # lsof -p 501
> COMMAND PID USER   FD   TYPE             DEVICE SIZE/OFF     NODE NAME
> pcscd   501 root  cwd   VDIR              0,113     1024        2 /
> pcscd   501 root  rtd   VDIR              0,113     1024        2 /
> pcscd   501 root  txt   VREG              0,113   121992 15279826 /usr/local/sbin/pcscd
> pcscd   501 root  txt   VREG              0,113   151560 29294355 /libexec/ld-elf.so.1
> pcscd   501 root  txt   VREG              0,113    98016 29294906 /usr/lib/libusb.so.3
> pcscd   501 root  txt   VREG              0,113    27640 29294864 /usr/lib/librt.so.1
> pcscd   501 root  txt   VREG              0,113   135712 29293769 /lib/libthr.so.3
> pcscd   501 root  txt   VREG              0,113  2063072 29294412 /lib/libc.so.7
> pcscd   501 root  txt   VREG              0,113   135192 19033335 /usr/local/lib/pcsc/drivers/ifd-ccid.bundle/Contents/FreeBSD/libccid.so
> pcscd   501 root    0r  VCHR               0,43      0t0       43 /dev/null
> pcscd   501 root    1u  VREG              0,113 35688824    11580 / (/dev/ada0p2)
> pcscd   501 root    2u  VREG              0,113 35688824    11580 / (/dev/ada0p2)
> pcscd   501 root    3u  VREG              0,113 35688824    11580 / (/dev/ada0p2)
> pcscd   501 root    4u  PIPE 0xfffff800162fd8e8    16384          ->0xfffff800162fda50
> pcscd   501 root    5u  PIPE 0xfffff800162fda50        0          ->0xfffff800162fd8e8
> pcscd   501 root    6u  unix 0xfffff800164036d0      0t0          /var/run/pcscd/pcscd.comm
> pcscd   501 root    7u  unix 0xfffff80016feaa38      0t0          /var/run/pcscd/pcscd.comm
> pcscd   501 root    9u  PIPE 0xfffff800162fd2f8    16384          ->0xfffff800162fd460, cnt=2, in=2
> pcscd   501 root   10u  PIPE 0xfffff800162fd460        0          ->0xfffff800162fd2f8
> pcscd   501 root   11u  PIPE 0xfffff800162f28e8    16384          ->0xfffff800162f2a50
> pcscd   501 root   12u  PIPE 0xfffff800162f2a50        0          ->0xfffff800162f28e8
> pcscd   501 root   13u  VCHR               0,87      0t0       87 /dev/usb/0.4.0
> pcscd   501 root   14u  VCHR               0,87      0t0       87 /dev/usb/0.4.0
> 
> $ gpg2 --card-status
> Reader ...........: Identiv uTrust 3512 SAM slot Token (55511725600891) 00 00
> Application ID ...: D27600012401020100050000532B0000
> Version ..........: 2.1
> Manufacturer .....: ZeitControl
> Serial number ....: 0000532B
> Name of cardholder: Matthias Apitz
> ...
> 
> 
> When I withdraw the OpenPGP card devd(8) hooks kill that proc and
> restarts a new one on card insert. But this new proc hangs.
> 
> The same happens when I disable the devd(8) start of this proc and start
> the same proc from a shell (for debugging). This hangs too.
> 
> Looks like something makes the USB stack broken after the point where
> devd(8) can launch fine the first proc of pcscd.
> 
>> Any error messages in dmesg?
> 

Hi,

> Nothing. Only on boot it sees the card:

And you are using the latest version of pcsd ?

> Jan  2 11:25:39 c720-r342378 kernel: ugen0.1: <0x8086 XHCI root HUB> at usbus0
> Jan  2 11:25:39 c720-r342378 kernel: ugen1.1: <Intel EHCI root HUB> at usbus1
> Jan  2 11:25:39 c720-r342378 kernel: ugen1.2: <vendor 0x8087 product 0x8000> at usbus1
> Jan  2 11:25:39 c720-r342378 kernel: ugen0.2: <SunplusIT Inc HD WebCam> at usbus0
> Jan  2 11:25:39 c720-r342378 kernel: ugen0.3: <vendor 0x0489 product 0xe056> at usbus0
> Jan  2 11:25:39 c720-r342378 kernel: ugen0.4: <Identiv uTrust 3512 SAM slot Token> at usbus0

There has been some changes in libusb recently .

What does "procstat -ak" output. Does it hang on any "usb" functions?

--HPS