Re: [usb-storage] Re: Amazon Kindle disconnect after Synchronize Cache

[Alan Stern <stern@rowland.harvard.edu>]

On Mon, Mar 08, 2021 at 10:59:48PM +0100, Matthias Schwarzott wrote:
> Am 07.03.21 um 17:58 schrieb Alan Stern:

> > Okay.  Can you collect a usbmon trace showing the events leading up to
> > and including a disconnection?
> > 
> The easiest reproducer is by calling sync while having a file/the device
> open (and keeping it open afterwards).
> 
> 1. I recorded usbmon trace like this:
> # cat /sys/kernel/debug/usb/usbmon/3u >
> /tmp/connect-python-sync-disconnect-usbmon.out
> 
> 2. Connect Kindle device
> 
> 3. Then trigger sync with python:
> # python -c "import time; import os; f = open('/dev/sde', 'r+b');
> time.sleep(1); os.fsync(f); time.sleep(5)"
> 
> 4. After 2 seconds Kindle disconnects (does no longer show USB-Mode screen).
> 
> 5. Ctrl+c the recording
> 
> When the final sleep in the python-command is missing, the Kindle does not
> disconnect.
> 
> > Alan Stern
> > 
> > PS: I suspect the SYNCHRONIZE CACHE commands are correlated with the
> > disconnections but don't cause them.  That is, I suspect the
> > disconnections happen when the device has been idle -- and generally the
> > host computer sends a SYNCHRONIZE CACHE command before idling a
> > removable drive.
> > 
> 
> I cannot read the usbmon trace, but wireshark displayed a command "SCSI:
> Prevent/Allow Medium Removal LUN: 0x00  ALLOW" when closing the file.
> So I suspect this command also counts as activity (!idle).

Here is the revelant part of the usbmon trace.  The second value on each 
line is a timestamp in microseconds.

> ffff88814e50d0c0 2440334800 S Bo:3:039:1 -115 31 = 55534243 79000000 00000000 00000600 00000000 00000000 00000000 000000
> ffff88814e50d0c0 2440334822 C Bo:3:039:1 0 31 >
> ffff88814e50d0c0 2440334824 S Bi:3:039:1 -115 13 <
> ffff88814e50d0c0 2440334909 C Bi:3:039:1 0 13 = 55534253 79000000 00000000 00

That is a TEST UNIT READY command, showing normal status.

> ffff88814e50d0c0 2440334922 S Bo:3:039:1 -115 31 = 55534243 7a000000 00000000 0000061e 00000001 00000000 00000000 000000
> ffff88814e50d0c0 2440334949 C Bo:3:039:1 0 31 >
> ffff88814e50d0c0 2440334951 S Bi:3:039:1 -115 13 <
> ffff88814e50d0c0 2440335817 C Bi:3:039:1 0 13 = 55534253 7a000000 00000000 00

That is a PREVENT MEDIUM REMOVAL command, sent when the device file was 
opened by the Python program.

> ffff88814e50d0c0 2441336674 S Bo:3:039:1 -115 31 = 55534243 7b000000 00000000 00000a35 00000000 00000000 00000000 000000
> ffff88814e50d0c0 2441336697 C Bo:3:039:1 0 31 >
> ffff88814e50d0c0 2441336699 S Bi:3:039:1 -115 13 <
> ffff88814e50d0c0 2441336911 C Bi:3:039:1 0 13 = 55534253 7b000000 00000000 00

That is the SYNCHRONIZE CACHE command.  Notice that the timestamp shows 
it occurred one second after the PREVENT MEDIUM REMOVAL.

> ffff88814e50d0c0 2442346649 S Bo:3:039:1 -115 31 = 55534243 7c000000 00000000 00000600 00000000 00000000 00000000 000000
> ffff88814e50d0c0 2442346700 C Bo:3:039:1 0 31 >
> ffff88814e50d0c0 2442346702 S Bi:3:039:1 -115 13 <
> ffff88814e50d0c0 2442346799 C Bi:3:039:1 0 13 = 55534253 7c000000 00000000 00

One second later, a normal TEST UNIT READY.

> ffff88814e50d0c0 2444394684 S Bo:3:039:1 -115 31 = 55534243 7d000000 00000000 00000600 00000000 00000000 00000000 000000
> ffff88814e50d0c0 2444394713 C Bo:3:039:1 0 31 >
> ffff88814e50d0c0 2444394720 S Bi:3:039:1 -115 13 <
> ffff88814e50d0c0 2444394804 C Bi:3:039:1 0 13 = 55534253 7d000000 00000000 01
> ffff88814e50d0c0 2444394821 S Bo:3:039:1 -115 31 = 55534243 7e000000 12000000 80000603 00000012 00000000 00000000 000000
> ffff88814e50d0c0 2444394866 C Bo:3:039:1 0 31 >
> ffff88822c917540 2444394928 S Bi:3:039:1 -115 18 <
> ffff88822c917540 2444395673 C Bi:3:039:1 0 18 = 70000200 0000000a 00000000 3a000000 0000
> ffff88814e50d0c0 2444395696 S Bi:3:039:1 -115 13 <
> ffff88814e50d0c0 2444395723 C Bi:3:039:1 0 13 = 55534253 7e000000 00000000 00

Two seconds later, another TEST UNIT READY.  This one returned a failure 
status, with an error code saying that the medium is not present (in 
spite of the fact that medium removal was supposed to be prevented).

The usbmon trace contains six more TEST UNIT READY commands, sent in 
quick succession, all getting the same failure result.  Notably, it does 
not show any sort of disconnection.  The final timestamp in the trace is 
2446328158, which is just five seconds after the SYNCHRONIZE CACHE 
command was sent -- there's no way to tell if anything happened after 
that.

Maybe there's something else going on under Windows that we're not aware 
of.  The only significant different I can see between this trace and the 
short Windows trace in your original email is the time interval between 
TEST UNIT READY commands; here it is two seconds but with Windows it was 
one second.  You can change the interval by writing to

	/sys/block/sde/events_poll_msecs

What happens if you set the value to 1000 before running the test?

Also, the usbmon trace shows that my guess about power management and 
device disconnections was completely wrong.  The bus does not get 
suspended and the Kindle does not disconnect, even though it seems to 
become unusable.

Alan Stern