Server crashes with "failed to fill whole buffer" when attaching kernel module

[estan]

@ellerh Hey, I tried following the instructions in the README, but when attaching the kernel module to the server with usbip attach -r 127.0.0.1 -d 1-1 the server crashes with:

estan@edison:~/orexplore/softfido$ target/debug/softfido --token-label softfido
softfido::crypto: Found secret key.
softfido::crypto: Found token counter. (0)
Softfido server running.
New connection Ok(TcpStream { addr: 127.0.0.1:3240, peer: 127.0.0.1:38300, fd: 5 })

OP_REQ_IMPORT
busid: 1-1
import request busid 1-1 complete
thread 'main' panicked at src/main.rs:47:52:
called `Result::unwrap()` on an `Err` value: Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
estan@edison:~/orexplore/softfido$

Running with RUST_BACKTRACE=full, the backtrace is:

estan@edison:~/orexplore/softfido$ RUST_BACKTRACE=full target/debug/softfido --token-label softfido
softfido::crypto: Found secret key.
softfido::crypto: Found token counter. (2)
Softfido server running.
New connection Ok(TcpStream { addr: 127.0.0.1:3240, peer: 127.0.0.1:44466, fd: 5 })

OP_REQ_IMPORT
busid: 1-1
import request busid 1-1 complete
thread 'main' panicked at src/main.rs:47:52:
called `Result::unwrap()` on an `Err` value: Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
stack backtrace:
   0:     0x5566754d6f7c - std::backtrace_rs::backtrace::libunwind::trace::hccf3cfe599d26745
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/../../backtrace/src/backtrace/libunwind.rs:104:5
   1:     0x5566754d6f7c - std::backtrace_rs::backtrace::trace_unsynchronized::hd3d8077f873485f2
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x5566754d6f7c - std::sys_common::backtrace::_print_fmt::h182daaf98b25bd14
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/sys_common/backtrace.rs:68:5
   3:     0x5566754d6f7c - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h4b6a846227d97bb7
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x556675502140 - core::fmt::rt::Argument::fmt::h9766ef94e9786c29
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/core/src/fmt/rt.rs:142:9
   5:     0x556675502140 - core::fmt::write::hb46e4cb217dc2581
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/core/src/fmt/mod.rs:1120:17
   6:     0x5566754d436f - std::io::Write::write_fmt::h0e754bba34fa795b
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/io/mod.rs:1810:15
   7:     0x5566754d6d64 - std::sys_common::backtrace::_print::h73ad48f083423281
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/sys_common/backtrace.rs:47:5
   8:     0x5566754d6d64 - std::sys_common::backtrace::print::h394692fca6f2f34a
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/sys_common/backtrace.rs:34:9
   9:     0x5566754d8367 - std::panicking::default_hook::{{closure}}::haa3c8a2ef3bd08de
  10:     0x5566754d80cf - std::panicking::default_hook::h37c8166f13b8b27c
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panicking.rs:292:9
  11:     0x5566754d87e8 - std::panicking::rust_panic_with_hook::h71d389cf21201b59
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panicking.rs:779:13
  12:     0x5566754d86ce - std::panicking::begin_panic_handler::{{closure}}::h655372ff562611b4
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panicking.rs:657:13
  13:     0x5566754d7446 - std::sys_common::backtrace::__rust_end_short_backtrace::h0e91de37c406f2fe
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/sys_common/backtrace.rs:171:18
  14:     0x5566754d8432 - rust_begin_unwind
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panicking.rs:645:5
  15:     0x55667530a5f5 - core::panicking::panic_fmt::h0290566811e2a53e
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/core/src/panicking.rs:72:14
  16:     0x55667530abe3 - core::result::unwrap_failed::he976b56b2f3075df
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/core/src/result.rs:1649:5
  17:     0x556675365eac - core::result::Result<T,E>::unwrap::h1d783792ff1d34a8
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/core/src/result.rs:1073:23
  18:     0x55667531ed79 - softfido::main::{{closure}}::h6448e8ba87f734f8
                               at /home/estan/orexplore/softfido/src/main.rs:47:13
  19:     0x556675325e07 - softfido::crypto::globals::with_ctx::ha15e4b258d00e171
                               at /home/estan/orexplore/softfido/src/crypto.rs:97:24
  20:     0x55667530db30 - softfido::main::h5fd3fa871463c8b6
                               at /home/estan/orexplore/softfido/src/main.rs:31:5
  21:     0x55667545f91b - core::ops::function::FnOnce::call_once::h1dfb12ea5c1d17c1
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/core/src/ops/function.rs:250:5
  22:     0x55667533690e - std::sys_common::backtrace::__rust_begin_short_backtrace::hdcdf338f5378fdcd
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/sys_common/backtrace.rs:155:18
  23:     0x556675342151 - std::rt::lang_start::{{closure}}::h6b186564db090002
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/rt.rs:167:18
  24:     0x5566754d0137 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::hd620b3b8c9654887
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/core/src/ops/function.rs:284:13
  25:     0x5566754d0137 - std::panicking::try::do_call::h319f4a718cea0bc5
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panicking.rs:552:40
  26:     0x5566754d0137 - std::panicking::try::h2c1b070ca4a247bb
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panicking.rs:516:19
  27:     0x5566754d0137 - std::panic::catch_unwind::h6a5d720b96964c71
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panic.rs:142:14
  28:     0x5566754d0137 - std::rt::lang_start_internal::{{closure}}::hbad653246307ad43
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/rt.rs:148:48
  29:     0x5566754d0137 - std::panicking::try::do_call::h83f4de88adc0ca5e
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panicking.rs:552:40
  30:     0x5566754d0137 - std::panicking::try::hd3793aaafcd95dda
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panicking.rs:516:19
  31:     0x5566754d0137 - std::panic::catch_unwind::h4b1c2658c4d0db72
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/panic.rs:142:14
  32:     0x5566754d0137 - std::rt::lang_start_internal::hcda365c9de08b755
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/rt.rs:148:20
  33:     0x55667534212a - std::rt::lang_start::h1d4091c4e86fda69
                               at /rustc/f967532a47eb728ada44473a5c4c2eca1a45fe30/library/std/src/rt.rs:166:17
  34:     0x55667530f2be - main
  35:     0x7f7872429d90 - __libc_start_call_main
                               at ./csu/../sysdeps/nptl/libc_start_call_main.h:58:16
  36:     0x7f7872429e40 - __libc_start_main_impl
                               at ./csu/../csu/libc-start.c:392:3
  37:     0x55667530aee5 - _start
  38:                0x0 - <unknown>
estan@edison:~/orexplore/softfido$

[estan]

Using Rust 1.76.0-nightly, running on Linux 6.2.0.

[ellerh]

Could you try the threads branch? That's what I'm using and I would like to merge that into master if it works.

[estan]

Hm, with the threads branch I get this when I try to attach the kernel module to the server:

estan@edison:~/orexplore/softfido$ usbip attach -r 127.0.0.1 -d 1-1
usbip: error: import device
estan@edison:~/orexplore/softfido$

While this happens, there's no additional output from the server, i.e:

estan@edison:~/orexplore/softfido$ target/debug/softfido --token-label softfido
softfido::crypto: Found secret key.
softfido::crypto: Found token counter. (67108868)
Softfido server is listening.

[ellerh]

usbip: error: import device

This could be permission problem. You must run usbip as root. Also try the --debug flag:
usbip --debug attach -r 127.0.0.1 -d 1-1 to get some feedback.

[estan]

Ah yes, my bad. Running usbip with sudo it works. Confirmed with lsusb -d 0:0 -v that the virtual USB device showed up.

However I'm not getting any popup when testing at on Yubico's test page or webauthn.io. Tested with Firefox 119 and Chromium 120, but they both just ask me to push my security key. Is the softfido server supposed to pop something up?

I have the following udev rule:

estan@edison:~$ cat /etc/udev/rules.d/90-hidraw.rules 
SUBSYSTEM=="hidraw", ATTRS{manufacturer}=="Fakecompany", \
,ATTRS{product}=="Softproduct", TAG+="uaccess", GROUP="plugdev", MODE="0660"
estan@edison:~$

Have rebooted my laptop since I added that, so it should be in effect. Do you know where below the /sys/class/hidraw directory the actual virtual USB device is, if I want to confirm permissions are set correctly by udev?

Thanks 🙏

[ellerh]

Confirmed with lsusb -d 0:0 -v that the virtual USB device showed up.

I just discovered that lsusb crashes the server: it sends a request for a DEBUG descriptor that wasn't handled (needed?) before. I added code for this case now and lsusb should complete normally. Please try the newest version of the threads branch.

Is the softfido server supposed to pop something up?

Yes, a dialog asking for "consent" should pop up.

Do you know where below the /sys/class/hidraw directory the actual virtual USB device is, if I want to confirm permissions are set correctly by udev?

For me ls -l /sys/class/hidraw shows:

lrwxrwxrwx 1 root root 0 Dec 14 08:29 hidraw0 -> ../../devices/pci0000:00/0000:00:1d.0/usb2/2-2/2-2:1.0/0003:046D:C31C.0004/hidraw/hidraw0
lrwxrwxrwx 1 root root 0 Dec 14 08:29 hidraw1 -> ../../devices/pci0000:00/0000:00:1d.0/usb2/2-2/2-2:1.1/0003:046D:C31C.0005/hidraw/hidraw1
lrwxrwxrwx 1 root root 0 Dec 14 10:22 hidraw2 -> ../../devices/platform/vhci_hcd.0/usb6/6-1/61:0.0/0003:0000:0000.001D/hidraw/hidraw2

The one with vhci_hcd interests us. The actual device /dev/hidraw2 should have permissions like:

shell> ls -l /dev/hidraw2 
crw-rw----+ 1 root plugdev 248, 2 Dec 14 10:22 /dev/hidraw2

[estan]

Thanks, hm, I pulled latest threads branch and tried:

1. Start server:

   estan@edison:~/orexplore/softfido$ target/debug/softfido --token-label softfido
   softfido::crypto: Found secret key.
   softfido::crypto: Found token counter. (67108870)
   Softfido server is listening.
   

2. Attach kernel module:

   estan@edison:~/orexplore/softfido$ sudo usbip attach -r 127.0.0.1 -d 1-1
   estan@edison:~/orexplore/softfido$
   

3. Check with lsusb -d 0:0 -v. Output: lsusb.txt

4. Check which hidraw devices I have:

   estan@edison:~$ ls -l /sys/class/hidraw
   totalt 0
   lrwxrwxrwx 1 root root 0 dec 15 19:39 hidraw0 -> ../../devices/platform/vhci_hcd.0/usb5/5-1/5-1:0.0/0003:0000:0000.0020/hidraw/hidraw0
   estan@edison:~$
   

5. Check ownership/permissions of hidraw0 device:

   estan@edison:~$ ls -l /dev/hidraw0 
   crw-rw----+ 1 root plugdev 240, 0 dec 15 19:39 /dev/hidraw0
   estan@edison:~$
   

6. Double-check I'm in plugdev group:

   estan@edison:~$ id estan
   uid=1000(estan) gid=1000(estan) grupper=1000(estan),4(adm),24(cdrom),27(sudo),30(dip),46(plugdev),116(lpadmin),126(sambashare),127(docker),129(kvm),998(softhsm)
   estan@edison:~$
   

7. Visit https://demo.yubico.com/webauthn-technical/registration in Firefox 119 and press Next. Firefox asks me to push my security key, but softfido server is not popping up any dialog. Same with Chromium 120.

During step (7), no further output is shown from softfido server besides what's shown above.

[ellerh]

Check with lsusb -d 0:0 -v. Output: lsusb.txt

Hmm, the line Couldn't open device, some information will be missing looks suspiscious. I don't see that on my machine.

During step (7), no further output is shown from softfido server besides what's shown above.

I added a --debug command line option to make the server more verbose. Maybe you could try that to get some clue.
I'm running a bit out of ideas what the problem could be. Maybe I need to test with a newer kernel.

[estan]

Alright, thanks. I pulled latest threads branch and tried running server with --debug.

During startup, the server now additionally prints:

softfido::ctaphid: start output loop
softfido::ctaphid: start input loop

When attaching the kernel module, the server prints:

softfido::usbip: TCP: TcpStream { addr: 127.0.0.1:3240, peer: 127.0.0.1:35856, fd: 5 }

softfido::usbip: REQ_IMPORT
softfido::usbip:  import request busid 1-1 complete
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 29 transfer: 64
softfido::usb: GET_DESCRIPTOR: type: Device index: 0 lang: 0 length: 64 
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 30 transfer: 18
softfido::usb: GET_DESCRIPTOR: type: Device index: 0 lang: 0 length: 18 
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 31 transfer: 9
softfido::usb: GET_DESCRIPTOR: type: Configuration index: 0 lang: 0 length: 9 
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 32 transfer: 41
softfido::usb: GET_DESCRIPTOR: type: Configuration index: 0 lang: 0 length: 41 
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 33 transfer: 255
softfido::usb: GET_DESCRIPTOR: type: String index: 0 lang: 0 length: 255 
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 34 transfer: 255
softfido::usb: GET_DESCRIPTOR: type: String index: 2 lang: 1033 length: 255 
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 35 transfer: 255
softfido::usb: GET_DESCRIPTOR: type: String index: 1 lang: 1033 length: 255 
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 36 transfer: 255
softfido::usb: GET_DESCRIPTOR: type: String index: 3 lang: 1033 length: 255 
softfido::usbip: handle_submit ep: 0 host->dev seqnum: 37 transfer: 0
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 38 transfer: 255
softfido::usb: GET_DESCRIPTOR: type: String index: 4 lang: 1033 length: 255 
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 39 transfer: 255
softfido::usb: GET_DESCRIPTOR: type: String index: 5 lang: 1033 length: 255 
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 40 transfer: 255
softfido::usb: GET_DESCRIPTOR: type: String index: 3 lang: 1033 length: 255 
softfido::usbip: handle_submit ep: 0 host->dev seqnum: 41 transfer: 0
softfido::usbip: handle_submit ep: 0 dev->host seqnum: 42 transfer: 30

But when visiting https://demo.yubico.com/webauthn-technical/registration in Firefox 119 and pressing Next, Firefox prompts me to push my security key, but there is no output from the softfido server.

Thanks, understood it is hard to debug this without hands-on access.

I may have some time to look closer at it during holidays.

Alright with me to close the issue if you want, since with the threads branch that issue seems resolved, while this is now something else.

Let me know if you need to know any sw versions besides the kernel and Rust.

[ellerh]

If you don't mind installing the Python libraries, you coud also try the tests in the python directory. This might give more useful error messages than Firefox. For that you need to install the fido2 library version 1.1 or so; version 0.9 no longer works.

To install the dependencies I did something like:
As root:sudo apt install python3-venv
as user:

cd python
python3 -m venv ~/softfido-venv
~/softfido-venv/bin/pip install fido2
~/softfido-venv/bin/python3 softfido_tests.py

Or run just a single test with

~/softfido-venv/bin/python3 softfido_tests.py Tests.test_info