Re: r342378: usbconfig takes 3-5 minutes to read the bus
El día viernes, enero 04, 2019 a las 10:09:27p. m. +0100, Hans Petter Selasky escribió: > On 1/4/19 7:31 PM, Matthias Apitz wrote: > > El día viernes, enero 04, 2019 a las 07:02:16p. m. +0100, Hans Petter > > Selasky escribió: > > > >> On 1/4/19 7:03 PM, Matthias Apitz wrote: > >>> I've applied the 2nd patch on the already patched sources, it fails. > >>> Should I use the original sources without your first patch? > >> > >> You should revert all prior patches. > > > > Done. Please find attached the messages. I did 'usbconfig list' and this > > is marked with this string in the messages. > > The attached log looks good. I assume the patch still fixes your issue - > right? > > https://svnweb.freebsd.org/changeset/base/342778 My son runs the same hardware Acer C720 with an older 12-CURRENT: $ uname -a FreeBSD c720-r314251-vale 12.0-CURRENT FreeBSD 12.0-CURRENT #1 r314251M: Tue Apr 2 07:19:39 CEST 2019 guru@c720-r314251-vale:/usr/obj/usr/src/sys/GENERIC amd64 Yesterday we wanted to connect a Canon EOS 300D camera to the USB port and it showed with gphoto2 the same delay problem. I applied the same patch to r314251 and all is fine. Thanks matthias -- Matthias Apitz, ✉ g...@unixarea.de, http://www.unixarea.de/ +49-176-38902045 Public GnuPG key: http://www.unixarea.de/key.pub AKL: "This U.E. is neo-liberalistic, anti-democratic and militaristic" AKL: "Diese EU ist neo-liberal, undemokratisch und militaristisch." signature.asc Description: PGP signature
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On Fri, 4 Jan 2019 22:09:27 +0100, Hans Petter Selasky wrote: > On 1/4/19 7:31 PM, Matthias Apitz wrote: >> El día viernes, enero 04, 2019 a las 07:02:16p. m. +0100, Hans >> Petter Selasky escribió: >> >>> On 1/4/19 7:03 PM, Matthias Apitz wrote: I've applied the 2nd patch on the already patched sources, it fails. Should I use the original sources without your first patch? >>> >>> You should revert all prior patches. >> >> Done. Please find attached the messages. I did 'usbconfig list' and this >> is marked with this string in the messages. > > The attached log looks good. I assume the patch still fixes your issue - > right? > > https://svnweb.freebsd.org/changeset/base/342778 > > --HPS Yes, thanks. The pcscd wotks with the token as it should. Thanks for wading through. matthias -- Sent using Dekko from my Ubuntu device http://www.unixarea.de/+49 176 38902045 ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/4/19 7:31 PM, Matthias Apitz wrote: El día viernes, enero 04, 2019 a las 07:02:16p. m. +0100, Hans Petter Selasky escribió: On 1/4/19 7:03 PM, Matthias Apitz wrote: I've applied the 2nd patch on the already patched sources, it fails. Should I use the original sources without your first patch? You should revert all prior patches. Done. Please find attached the messages. I did 'usbconfig list' and this is marked with this string in the messages. The attached log looks good. I assume the patch still fixes your issue - right? https://svnweb.freebsd.org/changeset/base/342778 --HPS ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
El día viernes, enero 04, 2019 a las 05:09:09p. m. +0100, Hans Petter Selasky escribió: > > Can you try this patch aswell and attach new logs? I've applied the 2nd patch on the already patched sources, it fails. Should I use the original sources without your first patch? mattias -- 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
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/4/19 5:05 PM, Hans Petter Selasky wrote:
On 1/4/19 4:27 PM, Matthias Apitz wrote:
El día viernes, enero 04, 2019 a las 12:45:47p. m. +0100, Hans Petter
Selasky escribió:
On 1/4/19 11:46 AM, Matthias Apitz wrote:
Jan 4 11:26:39 c720-r342378 kernel: uhub_read_port_status: port 13,
wPortStatus=0x07a0, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION
Jan 4 11:26:41 c720-r342378 kernel: uhub_read_port_status: port 1,
wPortStatus=0xe070, wPortChange=0x161e, err=USB_ERR_TIMEOUT
Jan 4 11:26:41 c720-r342378 kernel: uhub_read_port_status: port 2,
wPortStatus=0x0500, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION
Hi,
The problem appears to be that one of the USB HUBs port status request
don't respond: USB_ERR_TIMEOUT, which in turn blocks the enumeration
thread.
Can you try the attached kernel patch and send new debug log?
Hi,
I applied the patch and the new debug output is attached.
And it works now as it should, without any devd(8) hook. I just start
pcsdd as a service via rc.conf and can attach or withdraw the security
token. When the token is not attached GnuPG asks me to insert it and
when it is inserted I'm asked for the PIN. All as it should be
A big THANKS!
Should I file a PR to get your patch included upstream?
No PR needed, but I might need you to test one more patch.
Can you try this patch aswell and attach new logs?
Thank you!
--HPS
Index: sys/dev/usb/usb_hub.c
===
--- sys/dev/usb/usb_hub.c (revision 342455)
+++ sys/dev/usb/usb_hub.c (working copy)
@@ -129,6 +129,8 @@
int sc_disable_enumeration;
int sc_disable_port_power;
#endif
+ uint8_t sc_usb_port_errors; /* error counter */
+#define UHUB_USB_PORT_ERRORS_MAX 4
uint8_t sc_flags;
#define UHUB_FLAG_DID_EXPLORE 0x01
};
@@ -587,14 +589,26 @@
struct usb_port_status ps;
usb_error_t err;
+ if (sc->sc_usb_port_errors >= UHUB_USB_PORT_ERRORS_MAX) {
+ DPRINTFN(4, "port %d, HUB looks dead, too many errors\n", portno);
+ sc->sc_st.port_status = 0;
+ sc->sc_st.port_change = 0;
+ return (USB_ERR_TIMEOUT);
+ }
+
err = usbd_req_get_port_status(
sc->sc_udev, NULL, , portno);
- /* update status regardless of error */
+ if (err == 0) {
+ sc->sc_st.port_status = UGETW(ps.wPortStatus);
+ sc->sc_st.port_change = UGETW(ps.wPortChange);
+ sc->sc_usb_port_errors = 0;
+ } else {
+ sc->sc_st.port_status = 0;
+ sc->sc_st.port_change = 0;
+ sc->sc_usb_port_errors++;
+ }
- sc->sc_st.port_status = UGETW(ps.wPortStatus);
- sc->sc_st.port_change = UGETW(ps.wPortChange);
-
/* debugging print */
DPRINTFN(4, "port %d, wPortStatus=0x%04x, "
Index: sys/dev/usb/usb_request.c
===
--- sys/dev/usb/usb_request.c (revision 342455)
+++ sys/dev/usb/usb_request.c (working copy)
@@ -1601,8 +1601,9 @@
USETW(req.wValue, 0);
req.wIndex[0] = port;
req.wIndex[1] = 0;
- USETW(req.wLength, sizeof *ps);
- return (usbd_do_request(udev, mtx, , ps));
+ USETW(req.wLength, sizeof(*ps));
+
+ return (usbd_do_request_flags(udev, mtx, , ps, 0, NULL, 1000));
}
/**
___
freebsd-usb@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-usb
To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/4/19 4:27 PM, Matthias Apitz wrote: El día viernes, enero 04, 2019 a las 12:45:47p. m. +0100, Hans Petter Selasky escribió: On 1/4/19 11:46 AM, Matthias Apitz wrote: Jan 4 11:26:39 c720-r342378 kernel: uhub_read_port_status: port 13, wPortStatus=0x07a0, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 11:26:41 c720-r342378 kernel: uhub_read_port_status: port 1, wPortStatus=0xe070, wPortChange=0x161e, err=USB_ERR_TIMEOUT Jan 4 11:26:41 c720-r342378 kernel: uhub_read_port_status: port 2, wPortStatus=0x0500, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Hi, The problem appears to be that one of the USB HUBs port status request don't respond: USB_ERR_TIMEOUT, which in turn blocks the enumeration thread. Can you try the attached kernel patch and send new debug log? Hi, I applied the patch and the new debug output is attached. And it works now as it should, without any devd(8) hook. I just start pcsdd as a service via rc.conf and can attach or withdraw the security token. When the token is not attached GnuPG asks me to insert it and when it is inserted I'm asked for the PIN. All as it should be A big THANKS! Should I file a PR to get your patch included upstream? No PR needed, but I might need you to test one more patch. --HPS ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
El día viernes, enero 04, 2019 a las 12:45:47p. m. +0100, Hans Petter Selasky escribió: > On 1/4/19 11:46 AM, Matthias Apitz wrote: > > Jan 4 11:26:39 c720-r342378 kernel: uhub_read_port_status: port 13, > > wPortStatus=0x07a0, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION > > Jan 4 11:26:41 c720-r342378 kernel: uhub_read_port_status: port 1, > > wPortStatus=0xe070, wPortChange=0x161e, err=USB_ERR_TIMEOUT > > Jan 4 11:26:41 c720-r342378 kernel: uhub_read_port_status: port 2, > > wPortStatus=0x0500, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION > > Hi, > > The problem appears to be that one of the USB HUBs port status request > don't respond: USB_ERR_TIMEOUT, which in turn blocks the enumeration thread. > > Can you try the attached kernel patch and send new debug log? Hi, I applied the patch and the new debug output is attached. And it works now as it should, without any devd(8) hook. I just start pcsdd as a service via rc.conf and can attach or withdraw the security token. When the token is not attached GnuPG asks me to insert it and when it is inserted I'm asked for the PIN. All as it should be A big THANKS! Should I file a PR to get your patch included upstream? 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. Jan 4 16:19:15 c720-r342378 ipmon[738]: 16:19:15.433507 wlan0 @0:13 p 192.168.2.106,40444 -> 192.168.2.1,53 PR udp len 20 60 K-S OUT Jan 4 16:19:15 c720-r342378 ipmon[738]: 16:19:15.437243 wlan0 @0:13 p 192.168.2.1,53 -> 192.168.2.106,40444 PR udp len 20 76 K-S IN Jan 4 16:19:18 c720-r342378 kernel: uhub_read_port_status: port 1, Trying again, err=USB_ERR_TIMEOUT Jan 4 16:19:19 c720-r342378 kernel: uhub_read_port_status: port 1, wPortStatus=0x, wPortChange=0x, err=USB_ERR_TIMEOUT Jan 4 16:19:19 c720-r342378 kernel: uhub_read_port_status: port 2, wPortStatus=0x0500, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: usb_needs_explore: Jan 4 16:19:21 c720-r342378 kernel: usb_bus_powerd: bus=0xfe784428 Jan 4 16:19:21 c720-r342378 kernel: usb_bus_powerd: Recomputing power masks Jan 4 16:19:21 c720-r342378 kernel: uhub_explore: udev=0xf8000351c000 addr=1 Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 1, wPortStatus=0x07a0, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 2, wPortStatus=0x07a0, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 3, wPortStatus=0x0503, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 4, wPortStatus=0x0103, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 5, wPortStatus=0x0103, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 6, wPortStatus=0x07a0, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 7, wPortStatus=0x07a0, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 8, wPortStatus=0x07a0, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 9, wPortStatus=0x0780, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 10, wPortStatus=0x07a0, wPortChange=0x0020, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 11, wPortStatus=0x07a0, wPortChange=0x0020, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 12, wPortStatus=0x07a0, wPortChange=0x0020, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 13, wPortStatus=0x07a0, wPortChange=0x0020, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: usb_needs_explore: Jan 4 16:19:21 c720-r342378 kernel: usb_bus_powerd: bus=0xfe001ac4fcd8 Jan 4 16:19:21 c720-r342378 kernel: usb_bus_powerd: Recomputing power masks Jan 4 16:19:21 c720-r342378 kernel: uhub_explore: udev=0xf80003805000 addr=1 Jan 4 16:19:21 c720-r342378 kernel: uhub_read_port_status: port 1, wPortStatus=0x0503, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION Jan 4 16:19:21 c720-r342378 kernel: uhub_explore: udev=0xf800161e9000 addr=2 Jan 4 16:19:21 c720-r342378 kernel: usbd_transfer_power_ref: Adding type 0 to power state Jan 4 16:19:21 c720-r342378 kernel: usbd_transfer_power_ref: needs power Jan 4 16:19:22 c720-r342378 kernel: uhub_read_port_status: port 1, Trying
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/4/19 11:46 AM, Matthias Apitz wrote:
Jan 4 11:26:39 c720-r342378 kernel: uhub_read_port_status: port 13,
wPortStatus=0x07a0, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION
Jan 4 11:26:41 c720-r342378 kernel: uhub_read_port_status: port 1,
wPortStatus=0xe070, wPortChange=0x161e, err=USB_ERR_TIMEOUT
Jan 4 11:26:41 c720-r342378 kernel: uhub_read_port_status: port 2,
wPortStatus=0x0500, wPortChange=0x, err=USB_ERR_NORMAL_COMPLETION
Hi,
The problem appears to be that one of the USB HUBs port status request
don't respond: USB_ERR_TIMEOUT, which in turn blocks the enumeration thread.
Can you try the attached kernel patch and send new debug log?
--HPS
Index: sys/dev/usb/usb_hub.c
===
--- sys/dev/usb/usb_hub.c (revision 342455)
+++ sys/dev/usb/usb_hub.c (working copy)
@@ -590,11 +590,23 @@
err = usbd_req_get_port_status(
sc->sc_udev, NULL, , portno);
- /* update status regardless of error */
+ if (err != 0) {
+ DPRINTFN(4, "port %d, Trying again, err=%s\n",
+ portno, usbd_errstr(err));
- sc->sc_st.port_status = UGETW(ps.wPortStatus);
- sc->sc_st.port_change = UGETW(ps.wPortChange);
+ /* try a second time before giving up */
+ err = usbd_req_get_port_status(
+ sc->sc_udev, NULL, , portno);
+ }
+ if (err == 0) {
+ sc->sc_st.port_status = UGETW(ps.wPortStatus);
+ sc->sc_st.port_change = UGETW(ps.wPortChange);
+ } else {
+ sc->sc_st.port_status = 0;
+ sc->sc_st.port_change = 0;
+ }
+
/* debugging print */
DPRINTFN(4, "port %d, wPortStatus=0x%04x, "
Index: sys/dev/usb/usb_request.c
===
--- sys/dev/usb/usb_request.c (revision 342455)
+++ sys/dev/usb/usb_request.c (working copy)
@@ -1601,8 +1601,9 @@
USETW(req.wValue, 0);
req.wIndex[0] = port;
req.wIndex[1] = 0;
- USETW(req.wLength, sizeof *ps);
- return (usbd_do_request(udev, mtx, , ps));
+ USETW(req.wLength, sizeof(*ps));
+
+ return (usbd_do_request_flags(udev, mtx, , ps, 0, NULL, 1000));
}
/**
___
freebsd-usb@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-usb
To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/4/19 9:02 AM, Matthias Apitz wrote: We definitely should resolve this before anything else. The output of the 'usbconfig list' was: # usbconfig list ugen1.1: 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: at usbus0, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=ON (500mA) ugen1.2: at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA) ugen0.3: at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA) ugen0.4: at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA) Any comments on this ugen1.X? Hi, Can you collect USB HUB debug messages in dmesg? sysctl hw.usb.uhub.debug=16 Then reproduce then hang and send relevant output from "/var/log/messages". It seems to me like something is constantly keeping the USB enumeration thread busy. This can for example be: 1) fake USB plug/unplug events 2) pcscd going into a loop --HPS ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
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 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: 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 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,0x7fffe9ac) = 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,0x7fffe9ac) = 0 (0x0)
i.e. all openat(2) and ioctl(2) calls for /dev/ugen0.X devices are
normal, while the calls
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/3/19 1:36 PM, Ludovic Rousseau wrote:
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 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";
};
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.
Hi Matthias,
Can you try this:
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
--HPS
___
freebsd-usb@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-usb
To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
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 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";
> };
>
> 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
Bye
--
Dr. Ludovic Rousseau
___
freebsd-usb@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-usb
To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
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";
};
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.
--HPS
___
freebsd-usb@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-usb
To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
El día jueves, enero 03, 2019 a las 11:03:26a. m. +0100, Hans Petter Selasky
escribió:
> On 1/3/19 10:48 AM, Matthias Apitz wrote:
> > Is there a way log log any init call to libusb.so to see which process
> > is doing something with libusb.so after devd(8) started pcscd?
>
> Hi,
>
> You can add a print in the kernel sys/dev/usb/usb_generic.c in the function:
>
> static int
> ugen_open(struct usb_fifo *f, int fflags)
>
>
> printf("USB opened by PID %d %s\n", curthread->td_proc->p_pid,
> curthread->td_proc->p_comm);
Hi,
I've added the code and rebooted the new kernel. The only PID requesting
the ugen_open() is PID 544 pcscd, which is
$ dmesg | grep PID
...
USB opened by PID 544 pcscd
USB opened by PID 544 pcscd
USB opened by PID 544 pcscd
USB opened by PID 544 pcscd
USB opened by PID 544 pcscd
USB opened by PID 544 pcscd
$ ps ax | grep 544
544 v0- S 0:00,51 /usr/local/sbin/pcscd --debug --foreground
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:
notify 1000 {
match "system" "USB";
match "subsystem" "INTERFACE";
match "type" "ATTACH";
# uTrust
match "vendor" "0x04e6";
match "product" "0x5816";
action "logger CCID uTrust, type: $type, system: $system, subsystem:
$subsystem";
action "logger /usr/local/sbin/pcscd --debug --foreground ";
action "nohup /usr/local/sbin/pcscd --debug --foreground &";
};
#
notify 1000 {
match "system" "USB";
match "subsystem" "INTERFACE";
match "type" "ATTACH";
# HID Omnikey
match "vendor" "0x076b";
match "product" "0x6632";
action "logger CCID HID Omnikey, type: $type, system: $system,
subsystem: $subsystem";
action "logger /usr/local/sbin/pcscd --debug --foreground ";
action "nohup /usr/local/sbin/pcscd --debug --foreground & ";
};
#
notify 1000 {
match "system" "USB";
match "subsystem" "INTERFACE";
match "type" "DETACH";
# uTrust
match "vendor" "0x04e6";
match "product" "0x5816";
action "logger CCID uTrust, type: $type, system: $system, subsystem:
$subsystem";
action "logger killall pcscd";
action "killall pcscd";
};
#
notify 1000 {
match "system" "USB";
match "subsystem" "INTERFACE";
match "type" "DETACH";
# HID Omnikey
match "vendor" "0x076b";
match "product" "0x6632";
action "logger CCID HID Omnikey, type: $type, system: $system,
subsystem: $subsystem";
action "logger killall pcscd";
action "killall pcscd";
};
--
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
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/3/19 10:48 AM, Matthias Apitz wrote:
Is there a way log log any init call to libusb.so to see which process
is doing something with libusb.so after devd(8) started pcscd?
Hi,
You can add a print in the kernel sys/dev/usb/usb_generic.c in the function:
static int
ugen_open(struct usb_fifo *f, int fflags)
printf("USB opened by PID %d %s\n", curthread->td_proc->p_pid,
curthread->td_proc->p_comm);
Index: sys/dev/usb/usb_generic.c
===
--- sys/dev/usb/usb_generic.c (revision 342455)
+++ sys/dev/usb/usb_generic.c (working copy)
@@ -185,6 +185,8 @@
DPRINTFN(6, "flag=0x%x\n", fflags);
+ printf("USB opened by PID %d %s\n", curthread->td_proc->p_pid, curthread->td_proc->p_comm);
+
mtx_lock(f->priv_mtx);
switch (usbd_get_speed(f->udev)) {
case USB_SPEED_LOW:
--HPS
___
freebsd-usb@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-usb
To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
El día jueves, enero 03, 2019 a las 09:31:53a. m. +0100, Hans Petter Selasky
escribió:
> On 1/3/19 7:04 AM, Matthias Apitz wrote:
> > I think, we should isolate the problem from PCSC and focus (first) on the
> > question why are calls to usbconfig(8) are not answered anymore
> > *without* any kind of PCSC software being involved as I wrote in the
> > originating email of this thread. Here it is again in case in got lost
> > while talking about PCSC:
>
> Hi,
>
> Usually this happens if a user-space component is not closing its device
> handle while enumeration happens. Can you run pcsd in the foreground
> with debugging enabled and show what it prints while you plug unplug the
> device.
>
> Also try setting the hw.usb.uhub.debug=16 sysctl and collect messages in
> dmesg.
Hi,
I wasn't lazy and did several tests as root:
1. booting to single user mode with the token attached:
running usbconfig(8) works fine and fast; tested multiple times the
cmd, no delays;
2. booting to multiuser, login as root, no KDE started, just first login
as root in multiuser; devd(8) hook was moved away before booting;
running 'truss -o usbconfig.tr -d usbconfig list' gives the attached
output; long delays on open of the ugen0.X files:
3. re-boot again to multiuser, login as root, no KDE starting as root;
again without the devd(8) hook for the card:
running as root:
/usr/local/sbin/pcscd --debug --foreground > pcscd.stdout
gives:
pcscdaemon.c:347:main() pcscd set to foreground with debug send to
stdout
0554 configfile.l:361:DBGetReaderList() Parsing conf file:
/usr/local/etc/reader.conf.d
0062 pcscdaemon.c:662:main() pcsc-lite 1.8.23 daemon ready.
no reaction on plug-in or card detach; then I killed it with Ctrl-C
77360913 pcscdaemon.c:193:signal_thread() Received signal: 2
0063 pcscdaemon.c:226:signal_thread() Preparing for suicide
02189136 pcscdaemon.c:193:signal_thread() Received signal: 2
00639842 pcscdaemon.c:193:signal_thread() Received signal: 2
0055 pcscdaemon.c:247:signal_thread() Forced suicide
0020 pcscdaemon.c:785:at_exit() cleaning /var/run/pcscd
4. with devd(8) hook active, booted into multiuser the pcscd started by
devd(8) works fine until detaching the card (which let devd(8) kill
the running pcscd; a new started pcscd will not work anymore;
This means: something during boot damages the USB stack; this must be
something after devd(8) bring up pcscd (because this is still fine
working).
Is there a way log log any init call to libusb.so to see which process
is doing something with libusb.so after devd(8) started pcscd?
An option to test is deleting the devd(8) hooks for DETACH and
let pcscd just continue and see if ATTACH of the card works ...
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
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/3/19 7:04 AM, Matthias Apitz wrote: I think, we should isolate the problem from PCSC and focus (first) on the question why are calls to usbconfig(8) are not answered anymore *without* any kind of PCSC software being involved as I wrote in the originating email of this thread. Here it is again in case in got lost while talking about PCSC: Hi, Usually this happens if a user-space component is not closing its device handle while enumeration happens. Can you run pcsd in the foreground with debugging enabled and show what it prints while you plug unplug the device. Also try setting the hw.usb.uhub.debug=16 sysctl and collect messages in dmesg. --HPS ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
El día miércoles, enero 02, 2019 a las 05:04:42p. m. +0100, Hans Petter Selasky escribió: > Let's move this thread freebsd-usb only. > > Have a look here: > > https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=231076 I read carefully through the PR 231076 (and deleted freebsd-current from the mail thread). The PR does not match my problem. I think, we should isolate the problem from PCSC and focus (first) on the question why are calls to usbconfig(8) are not answered anymore *without* any kind of PCSC software being involved as I wrote in the originating email of this thread. Here it is again in case in got lost while talking about PCSC: If it would help, I could file a new separate PR with the dates below. I updated my amd64 laptop Acer C720 from r314251 to r342378. ... 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. Please, what can I check or enable to get additional logs for the problem. ... Ther first 3 commands usbconfig(8) are answered immediately, then it takes minutes to get any response. Why? # usbconfig list ugen1.1: 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: at usbus0, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=ON (500mA) ugen1.2: at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA) ugen0.3: at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA) ugen0.4: at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA) # usbconfig -d ugen0.4 list ugen0.4: at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA) # usbconfig -d ugen0.4 dump_device_desc ugen0.4: at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA) bLength = 0x0012 bDescriptorType = 0x0001 bcdUSB = 0x0200 bDeviceClass = 0x bDeviceSubClass = 0x bDeviceProtocol = 0x bMaxPacketSize0 = 0x0008 idVendor = 0x076b idProduct = 0x6632 bcdDevice = 0x0103 iManufacturer = 0x0001 iProduct = 0x0002 iSerialNumber = 0x bNumConfigurations = 0x0001 >From now it takes 3++ minutes to get the information from USB: # date ; usbconfig -d ugen0.4 dump_device_desc ; date Tue Jan 1 11:51:55 CET 2019 ugen0.4: at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA) bLength = 0x0012 bDescriptorType = 0x0001 bcdUSB = 0x0200 bDeviceClass = 0x bDeviceSubClass = 0x bDeviceProtocol = 0x bMaxPacketSize0 = 0x0008 idVendor = 0x076b idProduct = 0x6632 bcdDevice = 0x0103 iManufacturer = 0x0001 iProduct = 0x0002 iSerialNumber = 0x bNumConfigurations = 0x0001 Tue Jan 1 11:54:59 CET 2019 # date ; usbconfig -d ugen0.4 dump_device_desc ; date Tue Jan 1 14:30:19 CET 2019 ugen0.4: at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA) bLength = 0x0012 bDescriptorType = 0x0001 bcdUSB = 0x0200 bDeviceClass = 0x bDeviceSubClass = 0x bDeviceProtocol = 0x bMaxPacketSize0 = 0x0008 idVendor = 0x076b idProduct = 0x6632 bcdDevice = 0x0103 iManufacturer = 0x0001 iProduct = 0x0002 iSerialNumber = 0x bNumConfigurations = 0x0001 Tue Jan 1 14:34:05 CET 2019 # tail -f /var/log/messages ... Jan 1 14:34:30 c720-r342378 kernel: ugen0.4: at usbus0 (disconnected) Jan 1 14:34:36 c720-r342378 kernel: ugen0.4: at usbus0 # date ; usbconfig -d ugen0.4 dump_device_desc ; date Tue Jan 1 14:34:46 CET 2019 ugen0.4: at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA) bLength = 0x0012 bDescriptorType = 0x0001 bcdUSB = 0x0200 bDeviceClass = 0x bDeviceSubClass = 0x bDeviceProtocol = 0x bMaxPacketSize0 = 0x0008 idVendor = 0x076b idProduct = 0x6632 bcdDevice = 0x0103 iManufacturer = 0x0001 iProduct = 0x0002 iSerialNumber = 0x bNumConfigurations = 0x0001 Tue Jan 1 14:39:13 CET 2019 -- 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
Re: r342378: usbconfig takes 3-5 minutes to read the bus
El día miércoles, enero 02, 2019 a las 06:15:18p. m. +0100, Hans Petter Selasky escribió: > On 1/2/19 6:14 PM, Matthias Apitz wrote: > > On Wed, 2 Jan 2019 16:57:44 +0100, Hans Petter Selasky wrote: > >> On 1/2/19 4:47 PM, Matthias Apitz wrote: > >>> After card removal and insert devd(8) starts a new pcsd: > >> > >> Does pcsd install this devd(8) rule? I thought pcsd would no longer > >> need to be restarted. > >> > > > > They are made and used for years by me. > > Hi, > > You possibly need to kill pcsd with -KILL signal. Can you try to remove > that devd(8) rule and see what happens and start pcsd as a service. It > should no longer be needed. I did so (before reading your mail). When I start pcsd via /usr/local/etc/rc.d/pcsd (provided by the port), the boot hangs when pcsd is started. I will read later (maybe tomorrow) the PR you pointed me to. Thanks 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
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/2/19 6:14 PM, Matthias Apitz wrote: On Wed, 2 Jan 2019 16:57:44 +0100, Hans Petter Selasky wrote: On 1/2/19 4:47 PM, Matthias Apitz wrote: After card removal and insert devd(8) starts a new pcsd: Does pcsd install this devd(8) rule? I thought pcsd would no longer need to be restarted. They are made and used for years by me. Hi, You possibly need to kill pcsd with -KILL signal. Can you try to remove that devd(8) rule and see what happens and start pcsd as a service. It should no longer be needed. --HPS ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On Wed, 2 Jan 2019 16:57:44 +0100, Hans Petter Selasky wrote: > On 1/2/19 4:47 PM, Matthias Apitz wrote: >> After card removal and insert devd(8) starts a new pcsd: > > Does pcsd install this devd(8) rule? I thought pcsd would no longer > need to be restarted. > They are made and used for years by me. -- Sent using Dekko from my Ubuntu device http://www.unixarea.de/+49 176 38902045 ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/2/19 4:57 PM, Hans Petter Selasky wrote: On 1/2/19 4:47 PM, Matthias Apitz wrote: After card removal and insert devd(8) starts a new pcsd: Does pcsd install this devd(8) rule? I thought pcsd would no longer need to be restarted. > Let's move this thread freebsd-usb only. Have a look here: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=231076 --HPS ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
On 1/2/19 4:47 PM, Matthias Apitz wrote: After card removal and insert devd(8) starts a new pcsd: Does pcsd install this devd(8) rule? I thought pcsd would no longer need to be restarted. --HPS ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
El día miércoles, enero 02, 2019 a las 12:37:37p. m. +0100, Hans Petter Selasky escribió: > > Nothing. Only on boot it sees the card: > > And you are using the latest version of pcsd ? Yes. Compiled with all ports from December 23. > > > 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: at > > usbus1 > > Jan 2 11:25:39 c720-r342378 kernel: ugen1.2: > 0x8000> at usbus1 > > Jan 2 11:25:39 c720-r342378 kernel: ugen0.2: at > > usbus0 > > Jan 2 11:25:39 c720-r342378 kernel: ugen0.3: > 0xe056> at usbus0 > > Jan 2 11:25:39 c720-r342378 kernel: ugen0.4: > Token> at usbus0 > > There has been some changes in libusb recently . After card removal and insert devd(8) starts a new pcsd: Jan 2 16:39:11 c720-r342378 kernel: ugen0.4: at usbus0 Jan 2 16:39:11 c720-r342378 root[13636]: CCID uTrust, type: ATTACH, system: USB, subsystem: INTERFACE Jan 2 16:39:11 c720-r342378 root[13637]: /usr/local/sbin/pcscd --debug --foreground This sits hanging on /dev/usb/1.1.0: # lsof -p 13639 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME pcscd 13639 root cwd VDIR 0,113 10242 / pcscd 13639 root rtd VDIR 0,113 10242 / pcscd 13639 root txt VREG 0,113 121992 15279826 /usr/local/sbin/pcscd pcscd 13639 root txt VREG 0,113 151560 29294355 /libexec/ld-elf.so.1 pcscd 13639 root txt VREG 0,11398016 29294906 /usr/lib/libusb.so.3 pcscd 13639 root txt VREG 0,11327640 29294864 /usr/lib/librt.so.1 pcscd 13639 root txt VREG 0,113 135712 29293769 /lib/libthr.so.3 pcscd 13639 root txt VREG 0,113 2063072 29294412 /lib/libc.so.7 pcscd 13639 root0r VCHR 0,43 0t0 43 /dev/null pcscd 13639 root1u VCHR 0,43 0t0 43 /dev/null pcscd 13639 root2u VCHR 0,43 0t0 43 /dev/null pcscd 13639 root3u unix 0xf800609ff6d0 0t0 ->0xf800163fa368 pcscd 13639 root4u PIPE 0xf8004f13c2f816384 ->0xf8004f13c460 pcscd 13639 root5u PIPE 0xf8004f13c4600 ->0xf8004f13c2f8 pcscd 13639 root6u unix 0xf80072b03a38 0t0 /var/run/pcscd/pcscd.comm pcscd 13639 root7u PIPE 0xf8004e5422f816384 ->0xf8004e542460 pcscd 13639 root8u PIPE 0xf8004e5424600 ->0xf8004e5422f8 pcscd 13639 root9u PIPE 0xf8004e50900016384 ->0xf8004e509168 pcscd 13639 root 10u PIPE 0xf8004e5091680 ->0xf8004e509000 pcscd 13639 root 11u VCHR 0,52 0t0 52 /dev/usb/1.1.0 pcscd 13639 root 12u VCHR 0,52 0t0 52 /dev/usb/1.1.0 (note: the older working proc had open /dev/usb/0.4.0) > What does "procstat -ak" output. Does it hang on any "usb" functions? # ps ax | grep pcs 13639 - I 0:00,01 /usr/local/sbin/pcscd --debug --foreground 13967 4 S+ 0:00,01 grep pcs # procstat -k 13639 PIDTID COMMTDNAME KSTACK 13639 100287 pcscd - mi_switch sleepq_switch sleepq_catch_signals sleepq_wait_sig _sleep pipe_read dofileread kern_readv sys_read amd64_syscall fast_syscall_common 13639 100821 pcscd - mi_switch sleepq_switch sleepq_catch_signals sleepq_wait_sig _sleep pipe_read dofileread kern_readv sys_read amd64_syscall fast_syscall_common 13639 100822 pcscd - mi_switch sleepq_switch sleepq_catch_signals sleepq_wait_sig _sx_xlock_hard _sx_xlock usbd_enum_lock_sig usb_ref_device usb_open devfs_open VOP_OPEN_APV vn_open_vnode vn_open_cred kern_openat amd64_syscall fast_syscall_common 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. ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
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 10242 / pcscd 501 root rtd VDIR 0,113 10242 / 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,11398016 29294906 /usr/lib/libusb.so.3 pcscd 501 root txt VREG 0,11327640 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 1905 /usr/local/lib/pcsc/drivers/ifd-ccid.bundle/Contents/FreeBSD/libccid.so pcscd 501 root0r VCHR 0,43 0t0 43 /dev/null pcscd 501 root1u VREG 0,113 3568882411580 / (/dev/ada0p2) pcscd 501 root2u VREG 0,113 3568882411580 / (/dev/ada0p2) pcscd 501 root3u VREG 0,113 3568882411580 / (/dev/ada0p2) pcscd 501 root4u PIPE 0xf800162fd8e816384 ->0xf800162fda50 pcscd 501 root5u PIPE 0xf800162fda500 ->0xf800162fd8e8 pcscd 501 root6u unix 0xf800164036d0 0t0 /var/run/pcscd/pcscd.comm pcscd 501 root7u unix 0xf80016feaa38 0t0 /var/run/pcscd/pcscd.comm pcscd 501 root9u PIPE 0xf800162fd2f816384 ->0xf800162fd460, cnt=2, in=2 pcscd 501 root 10u PIPE 0xf800162fd4600 ->0xf800162fd2f8 pcscd 501 root 11u PIPE 0xf800162f28e816384 ->0xf800162f2a50 pcscd 501 root 12u PIPE 0xf800162f2a500 ->0xf800162f28e8 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 ...: D2760001240102010005532B Version ..: 2.1 Manufacturer .: ZeitControl Serial number : 532B 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: at usbus1 Jan 2 11:25:39 c720-r342378 kernel: ugen1.2: at usbus1 Jan 2 11:25:39 c720-r342378 kernel: ugen0.2: at usbus0 Jan 2 11:25:39 c720-r342378 kernel: ugen0.3: at usbus0 Jan 2 11:25:39 c720-r342378 kernel: ugen0.4: at usbus0 There has been some changes in libusb recently . What does "procstat -ak" output. Does it hang on any "usb" functions? --HPS ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
Re: r342378: usbconfig takes 3-5 minutes to read the bus
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? Any error messages in dmesg? --HPS ___ freebsd-usb@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/freebsd-usb To unsubscribe, send any mail to "freebsd-usb-unsubscr...@freebsd.org"
