Re: Yubikey uhid(4) problem? (PR 263995)

From: Christian Weisgerber <naddy_at_mips.inka.de>
Date: Thu, 19 May 2022 14:26:08 UTC
Hans Petter Selasky:

> usbdump
> 
> May help get the answer for that.
> 
> Look for USB_ERR_TIMEOUT .

Hmm.

So here is the output when authentication hangs:

$ doas usbdump -d0.2 -v
16:15:53.330564 usbus0.2 SUBM-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=64,IVAL=2
 frame[0] WRITE 64 bytes
16:15:53.330570 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:15:53.331882 usbus0.2 DONE-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=0,IVAL=2,ERR=0
 frame[0] WRITE 64 bytes

... and there it sits, until I terminate the ssh-sk-helper process.

16:16:15.485831 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=0,SLEN=0,IVAL=2,ERR=CANCELLED
^C
4 packets captured
1064 packets received by filter
0 packets dropped by kernel


By comparison, here's a successful authentication:

$ doas usbdump -d0.2 -v
16:16:38.644787 usbus0.2 SUBM-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=64,IVAL=2
 frame[0] WRITE 64 bytes
16:16:38.644794 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:38.645917 usbus0.2 DONE-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=0,IVAL=2,ERR=0
 frame[0] WRITE 64 bytes
16:16:38.646865 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:38.646879 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:38.647005 usbus0.2 SUBM-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=64,IVAL=2
 frame[0] WRITE 64 bytes
16:16:38.647865 usbus0.2 DONE-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=0,IVAL=2,ERR=0
 frame[0] WRITE 64 bytes
16:16:38.648862 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:38.648875 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:38.649860 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:38.649873 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:38.650862 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:38.650876 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:38.651864 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:38.651878 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:38.652305 usbus0.2 SUBM-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=256,IVAL=2
 frame[0] WRITE 256 bytes
16:16:38.655916 usbus0.2 DONE-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=0,IVAL=2,ERR=0
 frame[0] WRITE 256 bytes
16:16:38.884917 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:38.884933 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:39.171926 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:39.171942 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:39.459925 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:39.459941 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:39.746849 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:39.746864 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:40.033907 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:40.033924 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:40.321843 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:40.321857 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:40.608935 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:40.608951 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:40.867934 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:40.867951 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:40.868880 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:40.868896 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:40.869882 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:40.869898 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:40.870881 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:40.870897 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:40.871881 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=64,IVAL=2,ERR=0
 frame[0] READ 64 bytes
16:16:40.871896 usbus0.2 SUBM-INTR-EP=00000084,SPD=FULL,NFR=1,SLEN=0,IVAL=2
 frame[0] READ 64 bytes
16:16:40.872104 usbus0.2 SUBM-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=64,IVAL=2
 frame[0] WRITE 64 bytes
16:16:40.872926 usbus0.2 DONE-INTR-EP=00000004,SPD=FULL,NFR=1,SLEN=0,IVAL=2,ERR=0
 frame[0] WRITE 64 bytes
16:16:40.873622 usbus0.2 DONE-INTR-EP=00000084,SPD=FULL,NFR=0,SLEN=0,IVAL=2,ERR=CANCELLED
^C
44 packets captured
488 packets received by filter
0 packets dropped by kernel

-- 
Christian "naddy" Weisgerber                          naddy@mips.inka.de