udev access to SD card after using USBStorageDriver.write_image()

[csf-k]

If I set the mode of a SDMux from “host” to “dut” directly after using the write_image() method of labgrid.driver.usbsdmuxdriver, I get the following error message in dmesg:

[426904.365303] sdb: detected capacity change from 0 to 15704064
[426904.365817]  sdb: sdb1 sdb2
[426922.583978]  sdb: sdb1 sdb2
[426922.841343] sd 1:0:0:0: [sdb] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[426922.841360] sd 1:0:0:0: [sdb] tag#0 Sense Key : 0x3 [current] 
[426922.841364] sd 1:0:0:0: [sdb] tag#0 ASC=0x11 ASCQ=0x0 
[426922.841370] sd 1:0:0:0: [sdb] tag#0 CDB: opcode=0x28 28 00 00 00 03 08 00 00 f0 00
[426922.841374] critical medium error, dev sdb, sector 776 op 0x0:(READ) flags 0x84700 phys_seg 30 prio class 2
[426922.842150] sd 1:0:0:0: [sdb] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[426922.842155] sd 1:0:0:0: [sdb] tag#0 Sense Key : 0x2 [current] 
[426922.842159] sd 1:0:0:0: [sdb] tag#0 ASC=0x3a ASCQ=0x0 
[426922.842163] sd 1:0:0:0: [sdb] tag#0 CDB: opcode=0x28 28 00 00 00 03 f8 00 00 08 00
[426922.842166] I/O error, dev sdb, sector 1016 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 2
[426922.843641] sd 1:0:0:0: [sdb] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[426922.843652] sd 1:0:0:0: [sdb] tag#0 Sense Key : 0x2 [current] 
[426922.843656] sd 1:0:0:0: [sdb] tag#0 ASC=0x3a ASCQ=0x0 
[426922.843661] sd 1:0:0:0: [sdb] tag#0 CDB: opcode=0x28 28 00 00 00 03 08 00 00 08 00
[426922.843664] I/O error, dev sdb, sector 776 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[426922.843671] Buffer I/O error on dev sdb, logical block 97, async page read
[426922.849734] sdb: detected capacity change from 15704064 to 0

When investigating the cause of the error, I noticed that after write_image() the SD card is idle for approx. 100ms before it is used by udev for approx. 200ms. After that the SD card remains idle.

What is the recommended procedure to ensure that after executing write_image() the SD card is no longer used and it is safe to set the mode of the SDMux from "host" to "dut"?

[Emantor]

I wonder if this depends on the SD card or the SDMux. This should be fixed either in kernel (which shouldn't make the device available to userspace before it is usable) or the hardware itself if this is a hardware issue.

[jluebbe]

As this are only read requests, it might be partition uuid probing from userspace? With blktrace you should be able to see which process triggered these reads.

Is there a further issue beyond these messages appearing in the kernel log?

[csf-k]

I am sorry for the late reply.

I wonder if this depends on the SD card or the SDMux. This should be fixed either in kernel (which shouldn't make the device available to userspace before it is usable) or the hardware itself if this is a hardware issue.

I was able to reproduce the same error on a different exporter with a different SDMux and SD card (but same model).

As this are only read requests, it might be partition uuid probing from userspace? With blktrace you should be able to see which process triggered these reads.

I have problems interpreting the output generated by blktrace. What exactly should I look out for? This are the generated files:
blktrace.zip

Is there a further issue beyond these messages appearing in the kernel log?

No. The messages in the kenel log are the only issues I have observed so far.

[jluebbe]

I am sorry for the late reply.

No problem. Everyone is busy. :)

I wonder if this depends on the SD card or the SDMux. This should be fixed either in kernel (which shouldn't make the device available to userspace before it is usable) or the hardware itself if this is a hardware issue.

I was able to reproduce the same error on a different exporter with a different SDMux and SD card (but same model).

OK, this would be consistent with a software cause.

As this are only read requests, it might be partition uuid probing from userspace? With blktrace you should be able to see which process triggered these reads.

I have problems interpreting the output generated by blktrace. What exactly should I look out for? This are the generated files: blktrace.zip

For context: which blktrace commandline did you use?

Is there a further issue beyond these messages appearing in the kernel log?

No. The messages in the kenel log are the only issues I have observed so far.

OK. I'm not sure how soon we can find time to look at the trace.

[csf-k]

As this are only read requests, it might be partition uuid probing from userspace? With blktrace you should be able to see which process triggered these reads.

I have problems interpreting the output generated by blktrace. What exactly should I look out for? This are the generated files: blktrace.zip

For context: which blktrace commandline did you use?

To record the data I used the command: sudo blktrace -d /dev/sdb -o trace. Afterwards I was able to output the data with sudo blkparse trace.