libaums icon indicating copy to clipboard operation
libaums copied to clipboard
verified publisher icon magnusja

Error transferring command; errno 0 null

Open smoore6 opened this issue 5 years ago • 11 comments

Problem

Cannot write more than 100-ish files to the drive in a row, and drive loses connection. This is only happening on new drives that we are using, and cannot be reproduced on all drives. I have tried reformatting the drive and it does not help.

Expected behavior

To be able to continuously write files to the drive

Actual behavior

receive error when attempting to write the drive, and drive loses connection

Stacktrace of Excpetion

D/ClusterChain: Init a cluster chain, reading from FAT D/ClusterChain: Finished init of a cluster chain D/ClusterChain: grow chain D/FsInfoStructure: writing to device I/FAT: allocating clusters finished E/ScsiBlockDevice: Error transferring command; errno 0 null D/ScsiBlockDevice: Reset bulk-only mass storage W/ScsiBlockDevice: sending bulk only mass storage request D/ScsiBlockDevice: Trying to clear halt on both endpoints W/AndroidUsbCommunication: Clearing halt on endpoint UsbEndpoint[mAddress=130,mAttributes=2,mMaxPacketSize=512,mInterval=0] (direction 128) 2020-05-08 18:01:46.013 16002-16816/ W/AndroidUsbCommunication: Clearing halt on endpoint UsbEndpoint[mAddress=1,mAttributes=2,mMaxPacketSize=512,mInterval=0] (direction 0) E/ScsiBlockDevice: Error transferring command; errno 0 null D/ScsiBlockDevice: Trying to reset the device D/AndroidUsbCommunication: Performing native reset W/AndroidUsbCommunication: ioctl failed! errno 0 null W/AndroidUsbCommunication: USB device will likely require new discovery and permissions

I also see this when I run first aid on the drive following the issue:

/Backups/Nexus 6P/Camera/10H.jpg has too many clusters allocated (logical=0, physical=2195456)

Code where problem occurs

val buf = ByteArray(fileToWrite.chunkSize)
var count: Int
while (inputStream.read(buf).also { count = it } > 0) {
     outputStream.write(buf, 0, count)
}

smoore6 avatar May 08 '20 22:05 smoore6

Hey there,

so first of all I would make sure it is working properly with Total Commander (USB plugin) and USB Media Explorer. If they are working fine we can be sure that there is something in libaums we can do about it.

Related issues

There are some related issues like #237 and #209. The situation got better with #242 but is not entirely solved :/

libusb

Are you using libusb? If not please check it out here https://github.com/magnusja/libaums/tree/develop/libusbcommunication

This definitely helped to significantly reduce the occurrences of this issue.

https://github.com/magnusja/libaums#troubleshooting

magnusja avatar May 13 '20 10:05 magnusja

I tested with Total Commander and USB Media Explorer and it worked fine. I see the issue when I try and copy up to 500 pictures to the drive. I was able to copy ~1500 using Total Commander/USB Media Exploere.

I also tried libusb. There did seem to be a performance improvement, but the issue persists. Here is an updated stack trace:

D/ClusterChain: Init a cluster chain, reading from FAT
D/ClusterChain: Finished init of a cluster chain
D/ClusterChain: grow chain
D/FsInfoStructure: writing to device
E/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeBulkTransfer(JNIEnv *, jobject, jlong, jint, jbyteArray, jint, jint, jint):73 libusb_bulk_transfer returned -7
E/ScsiBlockDevice: Error transferring command; errno 0 null
D/ScsiBlockDevice: Reset bulk-only mass storage
W/ScsiBlockDevice: sending bulk only mass storage request
D/ScsiBlockDevice: Trying to clear halt on both endpoints
W/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeClearHalt(JNIEnv *, jobject, jlong, jint):98 libusb reset
D/ContentValues: libusb clearFeatureHalt returned kotlin.Unit
W/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeClearHalt(JNIEnv *, jobject, jlong, jint):98 libusb reset
D/ContentValues: libusb clearFeatureHalt returned kotlin.Unit
V/InputMethodManager: Starting input: tba=android.view.inputmethod.EditorInfo@4742f9a nm : com.simplifieditproducts.picturekeeperconnect ic=null
I/InputMethodManager: startInputInner - mService.startInputOrWindowGainedFocus
D/ConnectivityManager: unregisterNetworkCallback; CallingUid : 10211, CallingPid : 31846
V/InputMethodManager: Starting input: tba=android.view.inputmethod.EditorInfo@efb20ab nm : com.simplifieditproducts.picturekeeperconnect ic=null
I/InputMethodManager: startInputInner - mService.startInputOrWindowGainedFocus
D/ConnectivityManager: requestNetwork; CallingUid : 10211, CallingPid : 31846
W/System.err: java.lang.IllegalArgumentException: Expected receiver of type com.android.vending.billing.IInAppBillingService, but got android.os.BinderProxy
W/System.err:     at java.lang.reflect.Method.invoke(Native Method)
W/System.err:     at com.onesignal.TrackGooglePurchase$2.run(TrackGooglePurchase.java:146)
W/System.err:     at java.lang.Thread.run(Thread.java:764)
D/ViewRootImpl@966f4a8[MainActivityBilling]: MSG_RESIZED_REPORT: frame=Rect(0, 0 - 720, 1280) ci=Rect(0, 48 - 0, 0) vi=Rect(0, 48 - 0, 0) or=1
D/ViewRootImpl@966f4a8[MainActivityBilling]: Relayout returned: old=[0,0][720,1280] new=[0,0][720,1280] result=0x3 surface={valid=true 3421589504} changed=false
E/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeBulkTransfer(JNIEnv *, jobject, jlong, jint, jbyteArray, jint, jint, jint):73 libusb_bulk_transfer returned -7
E/ScsiBlockDevice: Error transferring command; errno 0 null
D/ScsiBlockDevice: Trying to reset the device
W/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeReset(JNIEnv *, jobject, jlong):92 libusb reset

smoore6 avatar May 13 '20 19:05 smoore6

Is that the whole stack trace? Does not seem that it crashed up to that point.

With the 64GB drives you provided I get this:

2020-05-25 13:30:01.756 459-2890/system_process D/WificondControl: Scan result ready event
2020-05-25 13:31:55.217 3640-3843/com.github.mjdev.usbfileman E/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeBulkTransfer(JNIEnv *, jobject, jlong, jint, jbyteArray, jint, jint, jint):73 libusb_bulk_transfer returned -7
2020-05-25 13:31:55.226 3640-3843/com.github.mjdev.usbfileman E/ScsiBlockDevice: Error transferring command; errno 0 null
2020-05-25 13:31:55.226 3640-3843/com.github.mjdev.usbfileman D/ScsiBlockDevice: Reset bulk-only mass storage
2020-05-25 13:31:55.226 3640-3843/com.github.mjdev.usbfileman W/ScsiBlockDevice: sending bulk only mass storage request
2020-05-25 13:31:55.687 3640-3843/com.github.mjdev.usbfileman D/ScsiBlockDevice: Trying to clear halt on both endpoints
2020-05-25 13:31:55.687 3640-3843/com.github.mjdev.usbfileman W/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeClearHalt(JNIEnv *, jobject, jlong, jint):98 libusb clear halt
2020-05-25 13:31:55.687 3640-3843/com.github.mjdev.usbfileman D/LibusbCommunication: libusb clearFeatureHalt returned -5
2020-05-25 13:31:55.687 3640-3843/com.github.mjdev.usbfileman W/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeClearHalt(JNIEnv *, jobject, jlong, jint):98 libusb clear halt
2020-05-25 13:31:55.687 3640-3843/com.github.mjdev.usbfileman D/LibusbCommunication: libusb clearFeatureHalt returned -5
2020-05-25 13:32:00.019 359-456/? D/hwcomposer: hw_composer sent 6 syncs in 691s
2020-05-25 13:32:01.288 3640-3843/com.github.mjdev.usbfileman E/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeBulkTransfer(JNIEnv *, jobject, jlong, jint, jbyteArray, jint, jint, jint):73 libusb_bulk_transfer returned -7
2020-05-25 13:32:01.288 3640-3843/com.github.mjdev.usbfileman E/ScsiBlockDevice: Error transferring command; errno 0 null
2020-05-25 13:32:01.288 3640-3843/com.github.mjdev.usbfileman D/ScsiBlockDevice: Trying to reset the device
2020-05-25 13:32:01.293 3640-3843/com.github.mjdev.usbfileman W/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeReset(JNIEnv *, jobject, jlong):92 libusb reset
2020-05-25 13:32:02.831 3640-3843/com.github.mjdev.usbfileman D/LibusbCommunication: libusb reset returned -5
2020-05-25 13:32:02.835 459-667/system_process D/UsbHostManager: Removed device at /dev/bus/usb/001/004: Picture Keeper Connect
2020-05-25 13:32:02.835 459-667/system_process I/UsbAlsaManager: USB Audio Device Removed: null
2020-05-25 13:32:02.836 3640-3843/com.github.mjdev.usbfileman E/MainActivity: error copying!
    java.io.IOException: Could not claim interface, errno: 0 null
        at me.jahnen.libaums.libusbcommunication.LibusbCommunication.resetDevice(LibusbCommunication.kt:91)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:163)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.write(ScsiBlockDevice.kt:282)
        at com.github.mjdev.libaums.driver.ByteBlockDevice.write(ByteBlockDevice.kt:104)
        at com.github.mjdev.libaums.fs.fat32.ClusterChain.write$libaums_debug(ClusterChain.kt:190)
        at com.github.mjdev.libaums.fs.fat32.FatFile.write(FatFile.kt:114)
        at com.github.mjdev.libaums.fs.UsbFileOutputStream.write(UsbFileOutputStream.kt:75)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.write(BufferedOutputStream.java:126)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.copyFile(MainActivity.java:564)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.copyDir(MainActivity.java:545)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.copyDir(MainActivity.java:543)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.doInBackground(MainActivity.java:589)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.doInBackground(MainActivity.java:517)
        at android.os.AsyncTask$2.call(AsyncTask.java:333)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:245)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)

It crashes because it cannot reclaim the USB interface, somehow Android rmeoves the device from the system.

The 32GB volume seems to work fine though, can you confirm that?

magnusja avatar May 25 '20 12:05 magnusja

After some more testing I am arriving at the following conclusions:

  1. At some point communication is timing out, but no clue why. This can happen immediately or relatively late when copying a larger file (1.5GB in my case), but it will happen.
  2. The reset and clear endpoint procedure never results in a successful write afterwards (in other words it is useless)
  3. The resetDevice procedure always results in the need for reenumeration which interrupts file transfer.
  4. The TotalCOmmander plugin crashes or hangs as well (no successful transfer of the 1.5GB file) although it usually is able to transfer much more data before crashing than libaums. Their reset and clear endpoint procedure is useless as well.

Logs

libaums with libusb crashing

  1. Error could not claim interface
2020-05-26 16:28:34.178 3738-3738/com.github.mjdev.usbfileman I/UsbMassStorageDevice: Found usb interface: UsbInterface[mId=0,mAlternateSetting=0,mName=null,mClass=8,mSubclass=6,mProtocol=80,mEndpoints=[
    UsbEndpoint[mAddress=1,mAttributes=2,mMaxPacketSize=512,mInterval=0]
    UsbEndpoint[mAddress=130,mAttributes=2,mMaxPacketSize=512,mInterval=0]]
2020-05-26 16:28:34.179 3738-3738/com.github.mjdev.usbfileman I/UsbMassStorageDevice: Found usb endpoint: UsbEndpoint[mAddress=1,mAttributes=2,mMaxPacketSize=512,mInterval=0]
2020-05-26 16:28:34.179 3738-3738/com.github.mjdev.usbfileman I/UsbMassStorageDevice: Found usb endpoint: UsbEndpoint[mAddress=130,mAttributes=2,mMaxPacketSize=512,mInterval=0]
2020-05-26 16:28:34.180 354-3677/system_process I/ActivityManager: START u0 {flg=0x10000000 cmp=com.android.systemui/.usb.UsbPermissionActivity (has extras)} from uid 1000
2020-05-26 16:28:34.182 3738-3738/com.github.mjdev.usbfileman D/MainActivity: USB device attached
2020-05-26 16:28:34.183 3738-3738/com.github.mjdev.usbfileman I/UsbMassStorageDevice: found usb device: /dev/bus/usb/001/004=UsbDevice[mName=/dev/bus/usb/001/004,mVendorId=2316,mProductId=17733,mClass=0,mSubclass=0,mProtocol=0,mManufacturerName=Simplified IT Products,mProductName=Picture Keeper Connect,mVersion=11.00,mSerialNumber=04112402000029,mConfigurations=[
    UsbConfiguration[mId=1,mName=null,mAttributes=128,mMaxPower=150,mInterfaces=[
    UsbInterface[mId=0,mAlternateSetting=0,mName=null,mClass=8,mSubclass=6,mProtocol=80,mEndpoints=[
    UsbEndpoint[mAddress=1,mAttributes=2,mMaxPacketSize=512,mInterval=0]
    UsbEndpoint[mAddress=130,mAttributes=2,mMaxPacketSize=512,mInterval=0]]]]
2020-05-26 16:28:34.183 3738-3738/com.github.mjdev.usbfileman I/UsbMassStorageDevice: Found usb interface: UsbInterface[mId=0,mAlternateSetting=0,mName=null,mClass=8,mSubclass=6,mProtocol=80,mEndpoints=[
    UsbEndpoint[mAddress=1,mAttributes=2,mMaxPacketSize=512,mInterval=0]
    UsbEndpoint[mAddress=130,mAttributes=2,mMaxPacketSize=512,mInterval=0]]
2020-05-26 16:28:34.183 3738-3738/com.github.mjdev.usbfileman I/UsbMassStorageDevice: Found usb endpoint: UsbEndpoint[mAddress=1,mAttributes=2,mMaxPacketSize=512,mInterval=0]
2020-05-26 16:28:34.183 3738-3738/com.github.mjdev.usbfileman I/UsbMassStorageDevice: Found usb endpoint: UsbEndpoint[mAddress=130,mAttributes=2,mMaxPacketSize=512,mInterval=0]
2020-05-26 16:28:34.216 668-668/com.android.systemui W/ActivityThread: handleWindowVisibility: no activity for token android.os.BinderProxy@e43955c
2020-05-26 16:28:34.259 388-502/? D/SurfaceFlinger: duplicate layer name: changing com.android.systemui/com.android.systemui.usb.UsbPermissionActivity to com.android.systemui/com.android.systemui.usb.UsbPermissionActivity#1
2020-05-26 16:28:34.426 3738-3864/com.github.mjdev.usbfileman E/UsbDeviceConnectionJNI: device is closed in native_claim_interface
2020-05-26 16:28:34.750 668-668/com.android.systemui I/Choreographer: Skipped 30 frames!  The application may be doing too much work on its main thread.
2020-05-26 16:28:34.912 354-509/system_process I/ActivityManager: Displayed com.android.systemui/.usb.UsbPermissionActivity: +724ms
2020-05-26 16:28:34.924 354-509/system_process I/ActivityManager: Displayed com.android.systemui/.usb.UsbResolverActivity: +725ms
2020-05-26 16:28:34.924 354-509/system_process I/ActivityManager: Displayed com.android.systemui/.usb.UsbPermissionActivity: +730ms
2020-05-26 16:28:35.244 3738-3864/com.github.mjdev.usbfileman E/UsbDeviceConnectionJNI: device is closed in native_claim_interface
2020-05-26 16:28:35.245 3738-3864/com.github.mjdev.usbfileman E/MainActivity: error copying!
    java.io.IOException: Could not claim interface, errno: 0 null
        at me.jahnen.libaums.libusbcommunication.LibusbCommunication.resetDevice(LibusbCommunication.kt:93)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:164)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.write(ScsiBlockDevice.kt:283)
        at com.github.mjdev.libaums.driver.ByteBlockDevice.write(ByteBlockDevice.kt:104)
        at com.github.mjdev.libaums.fs.fat32.ClusterChain.write$libaums_debug(ClusterChain.kt:232)
        at com.github.mjdev.libaums.fs.fat32.FatDirectory.write$libaums_debug(FatDirectory.kt:299)
        at com.github.mjdev.libaums.fs.fat32.FatDirectory.createFile(FatDirectory.kt:319)
        at com.github.mjdev.libaums.fs.fat32.FatDirectory.createFile(FatDirectory.kt:36)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.copyFile(MainActivity.java:553)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.copyDir(MainActivity.java:546)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.copyDir(MainActivity.java:544)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.copyDir(MainActivity.java:544)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.copyDir(MainActivity.java:544)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.doInBackground(MainActivity.java:590)
        at com.github.mjdev.libaums.usbfileman.MainActivity$CopyFolderToUsbTask.doInBackground(MainActivity.java:518)
        at android.os.AsyncTask$2.call(AsyncTask.java:333)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:245)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.lang.Thread.run(Thread.java:764)
2020-05-26 16:28:35.255 3738-3864/com.github.mjdev.usbfileman D/MainActivity: Found file raid6rec.mod with size 3368

pcap: https://nc.jahnen.me/s/M7GBM7C4FDZLkJy

  1. Error Operation timed out 
2020-05-26 16:35:48.626 4318-4355/com.github.mjdev.usbfileman D/ClusterChain: Init a cluster chain, reading from FAT
2020-05-26 16:35:48.626 4318-4355/com.github.mjdev.usbfileman D/ClusterChain: Finished init of a cluster chain
2020-05-26 16:35:48.626 4318-4355/com.github.mjdev.usbfileman D/ClusterChain: grow chain
2020-05-26 16:35:48.898 376-376/? I/[email protected]: type=1400 audit(0.0:1076): avc: denied { read } for name="capacity" dev="fuse" ino=8 scontext=u:r:hal_health_default:s0 tcontext=u:object_r:fuse:s0 tclass=file permissive=1
2020-05-26 16:35:48.898 376-376/? I/[email protected]: type=1400 audit(0.0:1077): avc: denied { open } for path="/dev/pipe/battery/BAT0/capacity" dev="fuse" ino=8 scontext=u:r:hal_health_default:s0 tcontext=u:object_r:fuse:s0 tclass=file permissive=1
2020-05-26 16:35:52.621 4318-4355/com.github.mjdev.usbfileman D/FsInfoStructure: writing to device
2020-05-26 16:35:52.628 4318-4355/com.github.mjdev.usbfileman I/FAT: allocating clusters finished
2020-05-26 16:35:52.644 375-522/? D/hwcomposer: hw_composer sent 24 syncs in 171s
2020-05-26 16:35:54.054 254-254/? I/hostapd: type=1400 audit(0.0:1079): avc: denied { net_admin } for capability=12 scontext=u:r:execns:s0 tcontext=u:r:execns:s0 tclass=capability permissive=1
2020-05-26 16:35:57.429 354-4291/system_process D/WificondControl: Scan result ready event
2020-05-26 16:38:23.920 849-849/? I/wpa_supplicant: wlan0: CTRL-EVENT-BEACON-LOSS 
2020-05-26 16:38:24.387 375-522/? D/hwcomposer: hw_composer sent 6 syncs in 152s
2020-05-26 16:38:25.920 849-849/? I/wpa_supplicant: wlan0: CTRL-EVENT-BEACON-LOSS 
2020-05-26 16:38:27.052 4318-4355/com.github.mjdev.usbfileman E/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeBulkTransfer(JNIEnv *, jobject, jlong, jint, jbyteArray, jint, jint, jint):73 libusb_bulk_transfer returned -7, Operation timed out
2020-05-26 16:38:27.054 4318-4355/com.github.mjdev.usbfileman E/ScsiBlockDevice: Error transferring command; errno 0 null
2020-05-26 16:38:27.054 4318-4355/com.github.mjdev.usbfileman D/ScsiBlockDevice: Trying to reset the device
2020-05-26 16:38:27.057 4318-4355/com.github.mjdev.usbfileman W/native_libusbcom: jint Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeReset(JNIEnv *, jobject, jlong):92 libusb reset
2020-05-26 16:38:28.586 4318-4355/com.github.mjdev.usbfileman D/LibusbCommunication: libusb reset returned -5
2020-05-26 16:38:28.629 354-655/system_process D/UsbHostManager: Removed device at /dev/bus/usb/001/007: Picture Keeper Connect
2020-05-26 16:38:28.629 354-655/system_process I/UsbAlsaManager: USB Audio Device Removed: null
2020-05-26 16:38:28.631 3975-3975/de.hechler.tcplugins.usbstick I/TCUSBSTICK.PlgSvc: onReceive
2020-05-26 16:38:28.631 3975-3975/de.hechler.tcplugins.usbstick I/TCUSBSTICK.PlgSvc: USB_DEVICE_DETACHED
2020-05-26 16:38:28.631 3975-3975/de.hechler.tcplugins.usbstick I/TCUSBPLUGIN.PlugFun: SENDING CHAGEDIR
2020-05-26 16:38:28.632 4318-4318/com.github.mjdev.usbfileman D/UsbDocumentProvider: detachDevice() UsbDevice[mName=/dev/bus/usb/001/007,mVendorId=2316,mProductId=17733,mClass=0,mSubclass=0,mProtocol=0,mManufacturerName=Simplified IT Products,mProductName=Picture Keeper Connect,mVersion=11.00,mSerialNumber=04112402000029,mConfigurations=[
    UsbConfiguration[mId=1,mName=null,mAttributes=128,mMaxPower=150,mInterfaces=[
    UsbInterface[mId=0,mAlternateSetting=0,mName=null,mClass=8,mSubclass=6,mProtocol=80,mEndpoints=[
    UsbEndpoint[mAddress=1,mAttributes=2,mMaxPacketSize=512,mInterval=0]
    UsbEndpoint[mAddress=130,mAttributes=2,mMaxPacketSize=512,mInterval=0]]]]
2020-05-26 16:38:28.633 4318-4318/com.github.mjdev.usbfileman D/UsbDocumentProvider: remove rootId 43949408
2020-05-26 16:38:28.634 3975-3975/de.hechler.tcplugins.usbstick I/TCUSBPLUGIN.PlugFun: CHANGEDIR RESULT: null
2020-05-26 16:38:28.634 3773-3773/com.android.documentsui I/ProvidersCache: Updating roots due to change at content://com.github.mjdev.libaums.storageprovider.documents/root
2020-05-26 16:38:28.634 4318-4318/com.github.mjdev.usbfileman D/MainActivity: USB device detached
2020-05-26 16:38:28.634 4318-4318/com.github.mjdev.usbfileman D/native_libusbcom: void Java_me_jahnen_libaums_libusbcommunication_LibusbCommunication_nativeClose(JNIEnv *, jobject, jlong, jint):39 close native libusb
2020-05-26 16:38:28.634 4318-4318/com.github.mjdev.usbfileman D/UsbDeviceConnectionJNI: close
2020-05-26 16:38:28.635 4318-4318/com.github.mjdev.usbfileman W/MainActivity: no device found!
2020-05-26 16:38:28.648 4318-4337/com.github.mjdev.usbfileman D/UsbDocumentProvider: queryRoots()
2020-05-26 16:38:28.650 3773-4421/com.android.documentsui I/ProvidersCache: Provider returned no roots. Possibly naughty: com.github.mjdev.libaums.storageprovider.documents
2020-05-26 16:38:29.535 4318-4355/com.github.mjdev.usbfileman E/UsbDeviceConnectionJNI: device is closed in native_claim_interface
2020-05-26 16:38:30.088 354-655/system_process D/UsbHostManager: USB device attached: vidpid 090c:4545 mfg/product/ver/serial Simplified IT Products/Picture Keeper Connect/11.00/04112402000029 hasAudio/HID/Storage: false/false/true
2020-05-26 16:38:30.106 354-655/system_process D/UsbDeviceDescriptor:   1 configs
2020-05-26 16:38:30.106 354-655/system_process D/UsbHostManager: Added device UsbDevice[mName=/dev/bus/usb/001/008,mVendorId=2316,mProductId=17733,mClass=0,mSubclass=0,mProtocol=0,mManufacturerName=Simplified IT Products,mProductName=Picture Keeper Connect,mVersion=11.00,mSerialNumber=04112402000029,mConfigurations=[
    UsbConfiguration[mId=1,mName=null,mAttributes=128,mMaxPower=150,mInterfaces=[
    UsbInterface[mId=0,mAlternateSetting=0,mName=null,mClass=8,mSubclass=6,mProtocol=80,mEndpoints=[
    UsbEndpoint[mAddress=1,mAttributes=2,mMaxPacketSize=512,mInterval=0]
    UsbEndpoint[mAddress=130,mAttributes=2,mMaxPacketSize=512,mInterval=0]]]]

pcap: https://nc.jahnen.me/s/aonDN4QRfbA6fsM

Total Commander

  1. Crash
2020-05-26 16:11:19.233 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.read(444e98a,64)
2020-05-26 16:11:19.241 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.write(444e98a,64)
2020-05-26 16:11:19.248 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.read(444e98a,64)
2020-05-26 16:11:19.261 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.write(2405,1)
2020-05-26 16:11:19.269 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.write(5e9a,1)
2020-05-26 16:11:19.280 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.write(445244a,64)
2020-05-26 16:11:19.547 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.read(444e98a,64)
2020-05-26 16:11:19.555 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.read(444e98a,64)
2020-05-26 16:11:19.563 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.write(444e98a,64)
2020-05-26 16:11:24.564 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.write FAILED at retry 1 [Size=32768]: write block 71625098 (32768) failed, missing=32768.
2020-05-26 16:11:30.240 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.write FAILED at retry 2 [Size=32768]: write block 71625098 (32768) failed, missing=32768.
2020-05-26 16:11:31.432 1833-1913/com.android.vending I/Finsky: [148] kpo.run(3): Stats for Executor: BlockingExecutor krn@2250743[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 17]
2020-05-26 16:11:31.432 1833-1913/com.android.vending I/Finsky: [148] kpo.run(3): Stats for Executor: LightweightExecutor krn@2ccb1c0[Running, pool size = 3, active threads = 0, queued tasks = 0, completed tasks = 73]
2020-05-26 16:11:31.729 1833-1913/com.android.vending I/Finsky: [148] kpo.run(3): Stats for Executor: bgExecutor krn@9d05ef9[Running, pool size = 4, active threads = 0, queued tasks = 0, completed tasks = 93]
2020-05-26 16:11:41.612 354-589/system_process D/WificondControl: Scan result ready event
2020-05-26 16:11:56.508 3058-3072/de.hechler.tcplugins.usbstick E/USBPLUG: usb.write FAILED at retry 3 [Size=32768]: write block 71625098 (32768) failed, missing=32768.
2020-05-26 16:11:57.600 3058-3072/de.hechler.tcplugins.usbstick E/TCUSBPLUGIN.PlugFun: class de.hechler.tcplugins.usbstick.usbdriver.UsbMassStorageReader$USBError - write block 71625098 (32768) failed, missing=32768.
    de.hechler.tcplugins.usbstick.usbdriver.UsbMassStorageReader$USBError: write block 71625098 (32768) failed, missing=32768.
        at de.hechler.tcplugins.usbstick.usbdriver.UsbDeviceMassStorageReader.internWrite(UsbDeviceMassStorageReader.java:562)
        at de.hechler.tcplugins.usbstick.usbdriver.UsbDeviceMassStorageReader.write(UsbDeviceMassStorageReader.java:515)
        at de.hechler.tcplugins.usbstick.usbdriver.MassStorageLunReader.write(MassStorageLunReader.java:30)
        at de.hechler.tcplugins.usbstick.DiskDriver.writeSectors(DiskDriver.java:1875)
        at de.hechler.tcplugins.usbstick.DiskDriver.access$300(DiskDriver.java:41)
        at de.hechler.tcplugins.usbstick.DiskDriver$FATPartitionFS.writeCluster(DiskDriver.java:1041)
        at de.hechler.tcplugins.usbstick.fat.FATDirEntryManager.createDirEntry(FATDirEntryManager.java:108)
        at de.hechler.tcplugins.usbstick.fat.FATDirectory.createDirEntry(FATDirectory.java:184)
        at de.hechler.tcplugins.usbstick.fat.FATClusterOutputImpl.close(FATClusterOutputImpl.java:109)
        at de.hechler.tcplugins.usbstick.genimpl.ClusterOutputStream.close(ClusterOutputStream.java:63)
        at de.hechler.tcplugins.usbstick.PluginFunctions.copyFile(PluginFunctions.java:1025)
        at de.hechler.tcplugins.usbstick.PluginFunctions.putFile(PluginFunctions.java:874)
        at com.android.tcplugins.FileSystem.IPluginFunctions$Stub.onTransact(IPluginFunctions.java:122)
        at android.os.Binder.execTransact(Binder.java:731)
2020-05-26 16:11:57.601 3058-3072/de.hechler.tcplugins.usbstick E/TCUSBPLUGIN.PlugFun: class java.lang.NullPointerException - Attempt to invoke virtual method 'java.util.List de.hechler.tcplugins.usbstick.fat.FATDirectory.getDirEntries()' on a null object reference
    java.lang.NullPointerException: Attempt to invoke virtual method 'java.util.List de.hechler.tcplugins.usbstick.fat.FATDirectory.getDirEntries()' on a null object reference
        at de.hechler.tcplugins.usbstick.fat.FATFileImpl.deleteDir(FATFileImpl.java:75)
        at de.hechler.tcplugins.usbstick.fat.FATFileImpl.delete(FATFileImpl.java:70)
        at de.hechler.tcplugins.usbstick.PluginFunctions.copyFile(PluginFunctions.java:1033)
        at de.hechler.tcplugins.usbstick.PluginFunctions.putFile(PluginFunctions.java:874)
        at com.android.tcplugins.FileSystem.IPluginFunctions$Stub.onTransact(IPluginFunctions.java:122)
        at android.os.Binder.execTransact(Binder.java:731)

pcap: https://nc.jahnen.me/s/tnEeFNWTkDGgBf8

  1. Hanging

pcap: https://nc.jahnen.me/s/cHSAFSZSGXnEFsF

Questions

  • Why can transfer TotalCommander much more data without a the USB device timing out?
  • Why is the pkacage length differerent? (shorter and always different with libaums, whereas with TC usually length 64)

magnusja avatar May 26 '20 15:05 magnusja

Hey @magnusja

Thanks for your inputs and analysis, it is very helpful.

Just adding some more background information:

  • The issue may also happen on 32GB, but with a much lower reproducible rate.
  • The issue doesn't have such a high reproducible rate on our old 64GB drives, but with our new 64GB drives the reproducible rate is very high. We've confirmed with the factory, the only major change they made was replacing the Micron brand NAND flash with a Sandisk brand one.

@smoore6 and I also have a new finding today, that the issue does NOT happen on USB 3.0 phones, we have two phones (Samsung Galaxy S8 and LG G6) which supports USB 3.0 SuperSpeed, and we are NOT able to reproduce the issue on them.

On the other hand, we can easily reproduce the issue on many USB 2.0 phones, and we realized some Android phones with Type-C connectors may still run on USB 2.0 speed.

The way we tell if the phone is USB 2.0 or 3.0 is using an app called 'USB Device Info', it will show the 'Max Packet Size' property of the device, which will be 512 for USB 2.0 (High Speed), and 1024 for USB 3.0 (SuperSpeed).

Screenshot_20200527-171358_USB Device Info

Some Questions:

  • Could it be power consumption related? We know that different NAND flashes may have different needs on power.
  • Why SAF works but libaums doesn't?
  • Is 'Max Packet Size' something that makes the difference? Or is it simply because USB 3.0 devices come with a high current than USB 2.0?

haoxi911 avatar May 27 '20 21:05 haoxi911

@smoore6 and I also have a new finding today, that the issue does NOT happen on USB 3.0 phones, we have two phones (Samsung Galaxy S8 and LG G6) which supports USB 3.0 SuperSpeed, and we are NOT able to reproduce the issue on them.

On the other hand, we can easily reproduce the issue on many USB 2.0 phones, and we realized some Android phones with Type-C connectors may still run on USB 2.0 speed.

That is quite interesting, unfortunately I cannot test this. In genymotion/VirtualBox I can only successfully attach a USB 2 host controller.

Some Questions:

* Could it be power consumption related? We know that different NAND flashes may have different needs on power.

I dont think so as this happens on my desktop machine and an emulator as well.

* Why SAF works but libaums doesn't?

Well, I guess that SAF is using features of the Linux kernel to mount USB devices and not the Android USB host API.

* Is 'Max Packet Size' something that makes the difference? Or is it simply because USB 3.0 devices come with a high current than USB 2.0?

For our problem this should not matter. WIth a larger packet size transfers are usually faster.

magnusja avatar Jun 04 '20 13:06 magnusja

Yea, the issue seems to be USB 2.0 only.

As you mentioned above, the Android system disconnected the USB device while the issue occurs. I am thinking what might cause the disconnection, will it disconnect when we send an invalid SCSI command?

I have a Beagle 480 USB Analyzer and I used it to capture USB packets, the highlighted line in the image below should be a WRITE 10, however its Command Status Wrapper was not there for some reason.

I have very limited knowledge on SCSI and USB, hopefully this won't mislead the discussion, please disregard if it doesn't make any sense :-)

Annotation 2020-05-17 214916

haoxi911 avatar Jun 04 '20 22:06 haoxi911

Can the transfer be trapped at the failed write then made to wait 10 seconds before searching for the device and attempting to repeat last write and continue? If so, we could eliminate heat as a possible factor, even if we expect it to have to do that a few times to complete a burn process.

This has been tried, at least by me since many times I stepped around in the debugger while this issue was going on. No, waiting won't do any good.

Can you please attach here the logcat including the part before the issue occurs? I'm expecting to see some attempted recovery steps.

Also if your device is rooted and you can provide the kernel log, that would help too.

depau avatar Jun 04 '20 23:06 depau

Relevant code, if you wanna give it a look: https://github.com/magnusja/libaums/blob/38d4a6b6f9e602f6148a5cc2234cd8c3382e86a3/libusbcommunication/src/main/java/me/jahnen/libaums/libusbcommunication/LibusbCommunication.kt#L81-L98

depau avatar Jun 04 '20 23:06 depau

Unfortunately this device doesn't have working root yet.

logcat libusb:I libaum:I eu.depau.etchdroid:I *:S comes up blank. 🙄

Will update when Huawei sort me a BL code.

Gen0 avatar Jun 05 '20 01:06 Gen0

Will update when Huawei sort me a BL code.

This may be the reason why you don't get the logs, at my old company I heard stories that you had to get into this weird "factory testing" menu in order to get full logcats on Huaweis. They didn't like Huawei :D

I may want to add to my backlog the implementation of some way to also log somewhere else so users don't have to deal with these shitty phone companies shenanigans 🤦‍♂️ Hopefully now that Google cut them off less people will buy Huawei devices, but since I now own a Xiaomi I know well MIUI sucks just as much. I'm on Lineage right now.

depau avatar Jun 06 '20 01:06 depau