Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SPI Support #125

Merged
merged 8 commits into from
Jun 24, 2021
Merged

SPI Support #125

merged 8 commits into from
Jun 24, 2021

Conversation

benzea
Copy link
Collaborator

@benzea benzea commented Jun 2, 2021

Implement SPI recording and reply with using a new ioctl format (recording/replay using the usual ioctl related commands for umockdev-run and umockdev-record).

This is not tested. Implemented on top of #124.

@benzea
Copy link
Collaborator Author

benzea commented Jun 2, 2021

@WeierAndreas or @mincrmatt12, is one of you possibly able to test this? I don't currently have an SPI device, and I have not actually tried to run this code in any way so far.

@benzea benzea marked this pull request as draft June 2, 2021 14:55
@mincrmatt12
Copy link

Alright, so I gave this a go and it didn't seem to work.

After running umockdev-record /dev/spidev0.0 > device.umockdev to successfully get a description file, I tried ../../umockdev/build/umockdev-record --ioctl /dev/spidev0.0=capture.ioctl -- ./examples/img-capture (where img-capture is the example in libfprint) to try and capture the read/writes, but while the program ran fine the resulting ioctl file only contained a header:

@DEV /dev/spidev0.0 (SPI)

Separately, the thing wouldn't even build without a few patches to do with input_event_sec/input_event_usec which I had to change to time.tv_sec and time.tv_usec wherever they appear, although given that the unit tests apparently still build on gh actions it might just be old versions of something.

Running it with UMOCKDEV_DEBUG=all set does suggest that umockdev is picking up on the SPI ioctls:

ioctl fd 3 request 40206B00: original, result 194
ioctl fd 3 request 40206B00: original, result 3
ioctl fd 3 request 40206B00: original, result 3
ioctl fd 3 request 40206B00: original, result 3
ioctl fd 3 request 40206B00: original, result 3
ioctl fd 3 request 40206B00: original, result 3
ioctl fd 3 request 40206B00: original, result 3
ioctl fd 3 request 40206B00: original, result 3
ioctl fd 3 request 40206B00: original, result 3
ioctl fd 3 request 40206B00: original, result 3
ioctl fd 3 request 40206B00: original, result 194

(*6B00 is indeed SPI_IOC_MESSAGE) but it doesn't seem to be writing them to the file, for whatever reason.

@benzea
Copy link
Collaborator Author

benzea commented Jun 2, 2021

ioctl fd 3 request 40206B00: original, result 3

Hmm, no, that message means that we are not interceptin the ioctl properly. It is the fallback that happens if the code decides to do nothing.

The question is what is going on. One thing one could do is adding logging into handle_ioctl in umockdev-spi.vala and run with G_MESSAGES_DEBUG=all.

This is confusing. With the (SPI) in the file, we are hitting the right code paths. And handle_ioctl should be overriden, and being called. But, it is not being handled, so either the vala code is explicitly returning -100 or we are not even calling out to vala.

Do you see the ioctl_emulate_open fd %i (%s): connected ioctl sockert message?

@mincrmatt12
Copy link

Sorry for the delay, just tried it again and got the entire log this time, here.

It doesn't appear to want to capture the SPI device based on:

Selected device 0 (ElanTech Embedded Fingerprint Sensor) claimed by elanspi driver
isatty(1): real function result: 0, returning that
(process:33643): libfprint-elanspi-DEBUG: 23:37:39.312: 32614532985: ../libfprint/drivers/elanspi.c:1525
testbed wrapped open64(/dev/spidev0.0) -> /dev/spidev0.0
script_record_open: fd 10 on device 153:0 is not recorded
isatty(1): real function result: 0, returning that
(process:33643): libfprint-image_device-DEBUG: 23:37:39.312: Image device open completed

This is from running ../../umockdev/build/umockdev-record --ioctl /dev/spidev0.0=capture.ioctl -- ./examples/img-capture > allstreams.txt 2>&1

@benzea
Copy link
Collaborator Author

benzea commented Jun 4, 2021

Uhh, could you really install the new umockdev version (or set LD_PRELOAD_PATH to include the build directory)?

I think what is happening is that you are using the new umockdev-record with the old preload library, and then the result is completely expected.

EDIT: You can also double check the right version is loaded. e.g. by using strace, inserting an obvious crash bug/error message or using lsof/inspecting /proc/$PID/maps while the application is running.

@mincrmatt12
Copy link

Ah, that was the problem. It does appear to record the ioctls now, but trying to play them back fails with an assert:

** Message: 00:23:59.698: umockdev-spi.vala:204: Got SPI message via ioctl
**
ERROR:../src/umockdev-spi.vala:306:umockdev_ioctl_spi_handler_real_handle_read_write: assertion failed: (left >= 0)
** (umockdev-run:71669): DEBUG: 00:23:59.698: umockdev-utils.vala:36: umockdev: caught signal 6, propagating to child

[2]    71669 abort (core dumped)  G_MESSAGES_DEBUG=all ./umockdev-run --device  --ioctl   udev

some gdb-ing seems to suggest that chunk in recording hasn't been populated. Actually, it wouldn't recognize the SPI device and tried to play it back as an ioctl-tree (I think the regex might be wrong) so I had to comment out the conditional and hardcode it to instantiate the spi object.

@benzea
Copy link
Collaborator Author

benzea commented Jun 5, 2021

Hm, need to check the regexp. Could you post the generated .ioctl file for me to look at?

The assert likely means that it is not read in correctly by the replayer.

@mincrmatt12
Copy link

mincrmatt12 commented Jun 5, 2021

Alright, here's the first couple hundred lines of it (truncated for privacy reasons): https://static.mm12.xyz/capture.ioctl. I will point out that this is from running my prototype code, not the actual driver (since it was easier to hack out the hid stuff from that), which uses read/write calls in addition to IOC_MESSAGE, but your code looks like it should support that.

EDIT: Here's the umockdev file as well: https://static.mm12.xyz/device.umockdev

@benzea
Copy link
Collaborator Author

benzea commented Jun 6, 2021

Haha, I wrote "%20x" rather than "%02x" and the hex code was space padded to 20 characters rather than zero padded to two characters.

I guess fixable using sed, but you can also just re-record, I suppose. Need to check the loading code to fail harder in this case.

EDIT: Looking at the code, the problem causing the assertion was a bug in the loader code.
EDIT2: And a non-greedy match helps for decoding the format

@mincrmatt12
Copy link

Alright so after trying this it's now getting stuck on trying to capture a write(...) call:

Found sensor ID 6 => [eFSA96SA] (96 X 96) Version = 1; OTP = 1
SoftwareReset...
ERROR: libumockdev-preload: emulation code requested invalid read from 0xffffbfe7 + 1
ERROR: libumockdev-preload: Error communicating with ioctl socket, errno: 14

** (umockdev-record:13880): CRITICAL **: 01:08:23.127: umockdev-ioctl.vala:536: Destroying IoctlClient with open stream!

Adding a debug print inside handle_write in the spi recorder class:

After hardcoded lookup: (96 x 96) Version = 1
Found sensor ID 6 => [eFSA96SA] (96 X 96) Version = 1; OTP = 1
SoftwareReset...
ERROR: libumockdev-preload: emulation code requested invalid read from 0x56c1b6f7 + 1
ERROR: libumockdev-preload: Error communicating with ioctl socket, errno: 14
** Message: 01:18:05.751: umockdev-spi.vala:434: Got write

** (umockdev-record:15904): CRITICAL **: 01:18:05.752: umockdev-ioctl.vala:536: Destroying IoctlClient with open stream!

@benzea
Copy link
Collaborator Author

benzea commented Jun 11, 2021

Alright so after trying this it's now getting stuck on trying to capture a write(...) call:

Hah! To fix alpine (different libc), I needed to force the ioctl request to be a 32bit unsigned integer. Doing that caused the data pointer of the write to be truncated. I pushed a fixup to change the location which will fix the issue.

If you provide me with the relevant information (new dump in the correct format, the umockdev file and which code to run), then I can also try it here. Might be simpler as I suspect there will be a few more stupid bugs like this one.

@martinpitt
Copy link
Owner

#124 landed, so this can be rebased now.

@mincrmatt12
Copy link

Alright, now recording works and generates files that look sensible. Unfortunately, trying to play them back segfaults somewhere in vala-generated code trying to free something on line 181, while trying to update chunk.tx. My vala knowledge is fairly limited, but I think it's double-freeing the buffer that spi_decode_hex creates for some reason.

I've updated the capture.ioctl at https://static.mm12.xyz/capture.ioctl if you want to play with the data. The binary it's running against is my prototype driver here, with the NO_HID define set to only test SPI emulation.

@benzea
Copy link
Collaborator Author

benzea commented Jun 16, 2021

OK, so I need to use pointers into the array, otherwise it will copy information …

With this, I can replay, but at the end it'll go into an infinite loop, trying to read more data than is in the recording and getting an error. Is that expected or should the application quit at the end of the replay?

EDIT: Looking at the program output (without a shitton of debugging), it seems quite expected.

@mincrmatt12
Copy link

Yeah, the prototype is supposed to run forever dumping frames; it's not exactly the greatest thing for testing a clean exit. Just tried the latest code, seems to work properly now!

Just for reference, I've still had to replace all instances of input_event_[u]sec with time.tv_[u]sec and word_delay_usecs with delay_usecs to get it to compile. Is this just something being too old on Ubuntu 18, since it seems like the CI builds are working fine?

@benzea
Copy link
Collaborator Author

benzea commented Jun 16, 2021

Right, word_delay_usecs was added in linux 5.1 it seems, we can just not use it (only actually used for an assert that does not really matter).

The input_event_sec might be a case where the LinuxFixes vapi should be used. Can you paste the error maybe?

Though, to be honest, Ubuntu 18 is rather old at this point, and we did drop support for older distributions to some extend. That said, if that is all you need, then it probably should be working.

@mincrmatt12
Copy link

The errors are all occurring after valac:

[2/11] Compiling C object libumockdev.so.0.3.0.p/meson-generated_src_umockdev.c.o
FAILED: libumockdev.so.0.3.0.p/meson-generated_src_umockdev.c.o 
cc -Ilibumockdev.so.0.3.0.p -I. -I.. -I../src -I/usr/include/glib-2.0 -I/usr/lib/x86_64-linux-gnu/glib-2.0/include -I/usr/include/gio-unix-2.0/ -fdiagnostics-color=always -pipe -D_FILE_OFFSET_BITS=64 -w -g -Werror -Werror=missing-prototypes -Werror=strict-prototypes -Werror=nested-externs -Werror=pointer-arith -Werror=implicit-function-declaration -Werror=pointer-arith -Werror=init-self -Werror=format-security -Werror=format=2 -Werror=unused-variable -Werror=return-type -Werror=uninitialized -fPIC -pthread -MD -MQ libumockdev.so.0.3.0.p/meson-generated_src_umockdev.c.o -MF libumockdev.so.0.3.0.p/meson-generated_src_umockdev.c.o.d -o libumockdev.so.0.3.0.p/meson-generated_src_umockdev.c.o -c libumockdev.so.0.3.0.p/src/umockdev.c
../src/umockdev.vala: In function ‘umockdev_testbed_load_evemu_events’:
../src/umockdev.vala:1010:38: error: ‘struct input_event’ has no member named ‘input_event_sec’
 1010 |                 delay = (int) (ev_sec - ev.input_event_sec) * 1000 + (int) (ev_usec - ev.input_event_usec) / 1000;
      |                                      ^
../src/umockdev.vala:1010:94: error: ‘struct input_event’ has no member named ‘input_event_usec’
 1010 |                 delay = (int) (ev_sec - ev.input_event_sec) * 1000 + (int) (ev_usec - ev.input_event_usec) / 1000;
      |                                                                                              ^
../src/umockdev.vala:1014:5: error: ‘struct input_event’ has no member named ‘input_event_sec’
 1014 |             ev.input_event_sec = ev_sec;
      |     ^
../src/umockdev.vala:1015:5: error: ‘struct input_event’ has no member named ‘input_event_usec’
 1015 |             ev.input_event_usec = ev_usec;
      |     ^
ninja: build stopped: subcommand failed.

There are also a number of similar failures in tests/test-umockdev.c as well as in one of the debug prints in src/libumockdev-preload.c. Though, if it's just an older/newer kernel thing I don't really mind if it doesn't work without tweaking on my old installations :)

@benzea
Copy link
Collaborator Author

benzea commented Jun 16, 2021

Woha, that is new in kernel 4.15, I doubt we care about compatibility with that at this point.

@benzea benzea force-pushed the benzea/spi branch 2 times, most recently from 198d10d to 6c0da6b Compare June 16, 2021 14:46
@benzea benzea marked this pull request as ready for review June 16, 2021 14:54
@mincrmatt12
Copy link

mincrmatt12 commented Jun 21, 2021

Alright, so I tried using this to replay a capture from libfprint proper, and it seems to be choking on the continuation transfers (since fpi-spi-transfer uses multiple xfers in one ioctl whereas my prototype doesn't).

(process:95185): libfprint-device-DEBUG: 15:24:41.644: Device reported open completion
(process:95185): libfprint-device-DEBUG: 15:24:41.644: Completing action FPI_DEVICE_ACTION_OPEN in idle!
(process:95185): libfprint-image_device-DEBUG: 15:24:41.644: Activating image device
(process:95185): libfprint-image_device-DEBUG: 15:24:41.644: Image device internal state change from FPI_IMAGE_DEVICE_STATE_INACTIVE to FPI_IMAGE_DEVICE_STATE_ACTIVATING
(process:95185): libfprint-SSM-DEBUG: 15:24:41.644: [elanspi] ELANSPI_INIT_NSTATES entering state 0
** (umockdev-run:95181): DEBUG: 15:24:41.645: umockdev-utils.vala:36: umockdev: caught signal 6, propagating to child

--- stderr ---
**
ERROR:../src/umockdev-spi.vala:315:umockdev_ioctl_spi_handler_real_handle_read_write: assertion failed: (left >= 0)
Traceback (most recent call last):
  File "/home/matthew/libfprint/tests/umockdev-test.py", line 110, in <module>
    capture()
  File "/home/matthew/libfprint/tests/umockdev-test.py", line 97, in capture
    '%s' % os.path.join(tmpdir, "capture.png")])
  File "/usr/lib/python3.6/subprocess.py", line 311, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['umockdev-run', '-d', '/home/matthew/libfprint/tests/elanspi/device-spi', '-d', '/home/matthew/libfprint/tests/elanspi/device-hidraw', '-i', '/dev/spidev0.0=/home/matthew/libfprint/tests/elanspi/capture.ioctl', '--', '/usr/bin/python3', '/home/matthew/libfprint/tests/capture.py', '/tmp/libfprint-umockdev-test-7si0w98z/capture.png']' died with <Signals.SIGABRT: 6>.

The ioctl file is on the elan-spi-new branch in libfprint in the normal test location if you want to try running it yourself.

EDIT: I tracked this down to a typo in umockdev-spi.vala:

--- a/src/umockdev-spi.vala
+++ b/src/umockdev-spi.vala
@@ -307,7 +307,7 @@ internal class IoctlSpiHandler : IoctlSpiBase {
 
                 if (trans > chunk.rx.length - replay_byte)
                     trans = chunk.rx.length - replay_byte;
-                left = chunk.tx.length - replay_byte - trans;
+                left = chunk.rx.length - replay_byte - trans;
 
                 Posix.memcpy(&rx.data[offset], &chunk.rx[replay_byte], trans);
                 /* We are happy. */

@benzea benzea force-pushed the benzea/spi branch 3 times, most recently from 3473f60 to 72fc103 Compare June 21, 2021 21:57
Signals should be emitted on both the IoctlClient and IoctlBase object,
but emission on the IoctlBase object was missing.
@benzea benzea mentioned this pull request Jun 24, 2021
@martinpitt
Copy link
Owner

Thanks @benzea : I didn't review this with a fine comb, but overall it makes sense to me. Not sure if you want to do the fd_map_get() deadlock fix here or in a separate PR, but let me know when you want to land this. Thanks!

@benzea
Copy link
Collaborator Author

benzea commented Jun 24, 2021

Thanks @benzea : I didn't review this with a fine comb, but overall it makes sense to me. Not sure if you want to do the fd_map_get() deadlock fix here or in a separate PR, but let me know when you want to land this. Thanks!

It really needs to go into here, because it only happens due to the added read/write emulation support.

Benjamin Berg added 6 commits June 24, 2021 17:34
This permits overriding the read/write handler for devices. Doing so
permits us to e.g. correctly emulate SPI devices which may be accessed
both through read/write and ioctl.

The default implementation is to fall back, which may e.g. pick the
underlying PTY that was created.

Note that read/write emulation using this method is not done for the
fallback ioctl emulation socket as that would result in uneccessary
overhead for script handlers. We also use a fine-grained lock for each
of the sockets in order to prevent deadlocks during replay.
The SPI recorder will write "@dev device (SPI)", which allows selecting
the SPI replayer when --ioctl is passed.
Dynamically select the SPI recorder if we are passed an SPI device
instead of using the generic ioctl tree recorder.

Closes: martinpitt#121
@benzea
Copy link
Collaborator Author

benzea commented Jun 24, 2021

@martinpitt OK, we are good to go now (>=5 runs and all clean). Thanks for your patience!

The problem was, the following:

  • ioctl/write/read happens
  • remote_emulate takes the lock
  • signal comes in
  • glib handles the signal, does a write
  • emulate_remote is called, can't get the lock, waits for itself

The fix is simple:

  1. Block all signals while we are in the emulation code (before taking any lock).
  2. Stop catching EINTR, because we don't need it anymore
  3. Explicitly link against pthread (otherwise ubuntu doesn't compile)

Copy link
Owner

@martinpitt martinpitt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Danke!

@martinpitt martinpitt merged commit 73286fc into martinpitt:master Jun 24, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants