MSC 3.0 issues on Linux

[dhalbert]

Commit: d613776
Ubuntu 16.04
Metro M0

With this build, CIRCUITPY appears and the REPL works. However, the second disk that does not exist stills seems to be causing problems. After a time, CPU consumption of /lib/systemd/systemd-udevd and /usr/lib/udisks2/udisksd rises dramatically, and the errors below are repeated in syslog many times. E

Interestingly, if the board is unplugged, the cpu consumption of the processes above rises even higher. Eventually the system-udevd and udisksd processes disappear from the high CPU listing, but they are still messed up (or perhaps have crashed): disks may fail to appear in /media even after replugging.
Doing sudo systemctl restart systemd-udevd makes things better.

Oct 25 23:04:34 salmonx systemd[988]: dev-disk-by\x2did-usb\x2dAdafruit_Industries_Metro_M0.device: Dev dev-disk-by\x2did-usb\x2dAdafruit_Industries_Metro_M0.device appeared twice with different sysfs paths /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.2/host7/target7:0:0/7:0:0:1/block/sde and /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.2/host6/target6:0:0/6:0:0:1/block/sdd
Oct 25 23:04:34 salmonx systemd[1]: dev-disk-by\x2did-usb\x2dAdafruit_Industries_Metro_M0.device: Dev dev-disk-by\x2did-usb\x2dAdafruit_Industries_Metro_M0.device appeared twice with different sysfs paths /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.2/host7/target7:0:0/7:0:0:1/block/sde and /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.2/host6/target6:0:0/6:0:0:1/block/sdd
Oct 25 23:04:34 salmonx systemd[988]: dev-disk-by\x2dpath-pci\x2d0000:00:1a.0\x2dusb\x2d0:1.4:1.2.device: Dev dev-disk-by\x2dpath-pci\x2d0000:00:1a.0\x2dusb\x2d0:1.4:1.2.device appeared twice with different sysfs paths /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.2/host7/target7:0:0/7:0:0:1/block/sde and /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.2/host6/target6:0:0/6:0:0:1/block/sdd
Oct 25 23:04:34 salmonx systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:1a.0\x2dusb\x2d0:1.4:1.2.device: Dev dev-disk-by\x2dpath-pci\x2d0000:00:1a.0\x2dusb\x2d0:1.4:1.2.device appeared twice with different sysfs paths /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.2/host7/target7:0:0/7:0:0:1/block/sde and /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.2/host6/target6:0:0/6:0:0:1/block/sdd
Oct 25 23:04:34 salmonx systemd-udevd[21461]: inotify_add_watch(9, /dev/sdd, 10) failed: No such file or directory

I changed mscdf_init(1); to mscdf_init(0); to eliminate the second disk, and tried again, and the errors did not reappear.

My guess is that the disks may appear to be the same disk appearing two places because the SCSI inquiry reponse doesn't fill in any ID info (it's all zeros). So a name is manufactured, based on some other ID's, but it's not unique across the two disks. The fix may be to put some ID info that differs into the query response.

There are some other weird issues, like sometimes the disk not appearing or the REPL not responding. But this may be due to lingering effects of the original duplicate disks.

[dhalbert]

I don't think this is exactly the issue but it indicates how systemd-udevd can go crazy:
https://sourceforge.net/p/cdemu/bugs/93/#fc7c
There are other examples of high cpu for that process with devices in Hyper-V, etc.

It may also indicate that eliminating the duplicate disk ids may or may not fix the problem (though it may eliminate some messages). If the missing disk is causing some kind of repeated event from the kernel, it could cause an issue. There are ways to monitor systemd-udevd and disksd that may be helpful.

[tannewt]

I'm seeing it repeatedly test that the unit is ready and then follow up with a request sense for more details on why its not ready. I'm playing around with the request sense response to see if I can get it to back off.

[tannewt]

Yup, I trusted the whole ERR_ABORTED thing too much. Changing it back to ERR_NOT_FOUND makes linux happy again.

The inquiry stuff was definitely wrong though. The read capacity response looks as it should.

[dhalbert]

Tested new PR's and the problem looks like it's fixed!

@tannewt Why not count how many filesystems there are and call mscdf_init() with that count? Or are you thinking they may be turned on and off dynamically after the USB descriptor has been sent? Or maybe there's an initialization order problem I'm not realizing.

[dastels]

What I'm seeing on Ubuntu 17.04 with Adafruit CircuitPython 3.0.0-alpha.0-1031-gee18b5cba on 2017-10-26; Metro M4 Express with samd51j19

If the board is reset with code in main.py, etc CIRCUITPY shows up, the code runs (in my case it blinks the LED and poutputs some text), the led blinks, and when I connect with screen I see the text. I cannot get into the repl, though.

If I then (from a terminal) remove the code on CIRCUITPY, I can get into the repl without problem. If I had tried to enter the repl while the code was running, I drop directly into it.

If I reset without code on CIRCUITPY, I can enter the repl as expected.

If main.py does not loop forever (i.e. it runs and hits the end), I can get into the repl when it ends.

This does tend to completely stop work/responding after a bit of experimenting, at least with the particular USB port..

[tannewt]

@dhalbert SD cards are never mounted when usb is inited because they currently require the Python VM. So, by supporting removable media we should be able to dynamically make it available.

@dastels that will still have the misleading inquiry response. try it with this latest commit. On my Arch linux box I see a warning about unable to get the write protect bit and the cache but it works otherwise.

[dhalbert]

If the board is reset with code in main.py, etc CIRCUITPY shows up, the code runs (in my case it blinks the LED and poutputs some text), the led blinks, and when I connect with screen I see the text. I cannot get into the repl, though.

This may be due to improper ctrl-C interrupt handling, or the setup for that is in the wrong place.

[tannewt]

This ASF4 change fixed this: adafruit/asf4@8e3e471

Before, ASF4 would respond as if the second drive existed even when we returned null as the inquiry result. Now, it responds with NOT_FOUND.