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

Could not write to device, result == -1 errno 0 null #237

Open
kuza2010 opened this issue Dec 10, 2019 · 63 comments
Open

Could not write to device, result == -1 errno 0 null #237

kuza2010 opened this issue Dec 10, 2019 · 63 comments

Comments

@kuza2010
Copy link

Hi, @magnusja
Libaums version 0.7.3

Hardware devices:

  • usb device 1: SanDisk dual-drive 128Gb with Fat32, 32/64 Kb cluster size;
  • usb device 2: JetFlash 8Gb with Fat32, 32/4 Kb cluster size;
  • android version 9(Samsung Galaxy S10e)/8(Xiaomi Redmi 5 Plus)

Problem

I try to copy about 1000 mixed size/type files (total size 2 Gb).

Expected behavior

Files were copied correctly.

Actual behavior

java.io.IOException: Could not write to device, result == -1 errno 0 null

Stacktrace of Excpetion

image

Code where problem occurs

UsbFileOutputStream.write(bytes);

Any hints!

Thanks a lot!

@magnusja
Copy link
Owner

Hey there,

I think this is realted to etchdroid/etchdroid#10

Apparently under Pie this issue has gotten a lot worse. @depau and I are working on a fix but as we are quite busy, this can still take a while. I hope I will have some time over the Christmas break.

@kuza2010
Copy link
Author

Hey, it seems good.
From my side, I will continue to investigate the issue.
Any questions, feel free!

Thanks a lot!

@depau
Copy link
Collaborator

depau commented Dec 19, 2019

Hi,
yep it looks like that issue.

Sadly I haven't been able to work on it the last few months. Hopefully I'll have some time in February, definitely not before that :(

@kuza2010
Copy link
Author

Hi,
Also, I found several similar problems:

I will try those tips and let you know if it works well for me.

@depau
Copy link
Collaborator

depau commented Dec 21, 2019

Those two links look unrelated to me.

In case anybody wants to dig into this issue and write some code before @magnusja and I have time, a few hints:

Here's some badly-taken notes: https://notes.depau.eu/ZkErsTYJQLC7AQJhcyn7VA#resetRecovery

Here's some sample code that needs testing and refinement. DO NOT blindly copy-paste, thanks ;)

private void resetRecovery() {
    bulkOnlyMassStorageReset();
    clearFeatureHALT(this.epIn);
}

private void bulkOnlyMassStorageReset() {
    byte[] bArr = new byte[2];
    // REQUEST_BULK_ONLY_MASS_STORAGE_RESET = 255
    // REQUEST_TYPE_BULK_ONLY_MASS_STORAGE_RESET = 33
    int controlTransfer = this.usbConn.controlTransfer(33, 255, 0, this.usbInterface.getId(), bArr, 0, 1000);
    // check if it succeeded
}

private void clearFeatureHalt(UsbEndpoint usbEndpoint) {
    byte[] bArr = new byte[2];
    int address = usbEndpoint.getAddress();
    // REQUEST_CLEAR_FEATURE = 1
    // REQUEST_TYPE_CLEAR_FEATURE = 2
    int controlTransfer = this.usbConn.controlTransfer(2, 1, 0, address, bArr, 0, 1000);
    // check if it succeeded
}

We basically need to implement these recovery reset methods. Whenever bulkOutTransfer returns -1 but errno is 0 or EPIPE, a reset must be done and a new attempt performed.

I think the "reset required detection" logic is best if implemented in ScsiBlockDevice.kt.

I would then place the actual reset methods in UsbCommunication.kt and its implementations. This way we can easily change implementations to work around different Android versions shenanigans; also we get a UsbEndpoint and UsbConnection for free.

Note that, however, we also require a UsbInterface reference. This is not available at the time in UsbCommunication, so you will need to patch UsbCommunicationFactory.kt and UsbMassStorageDevice.kt to hand it over.

@magnusja please review ↑ :)

@mannyzhao
Copy link

Hey, it seems good.
From my side, I will continue to investigate the issue.
Any questions, feel free!

Thanks a lot!
hey,Have you solved this problem, man

@kuza2010
Copy link
Author

kuza2010 commented Dec 27, 2019

Hey, it seems good.
From my side, I will continue to investigate the issue.
Any questions, feel free!
Thanks a lot!
hey,Have you solved this problem, man

Hi, @mannyzhao! Sorry to keep you waiting. Unfortunately no. I am still trying to find a solution

@magnusja
Copy link
Owner

magnusja commented Jan 4, 2020

Hey guys, can you please try #240

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

Well...
Screenshot-20200105-011831.png

This is Android 10 though :P I'm going to test it on my old phone with Android 9, and maybe set a few logging breakpoints to see if the new code is actually reached.

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

I can confirm it works on Android 9 too. However, I haven't seen the message logged for the reset procedure. The whole thing is quite weird.

I'll test it on the emulator, on which is was 100% required for whatever reason.

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

Nope, the issue eventually occurred and it looks like the patch didn't help:

D/ScsiBlockDevice: inquiry response: ScsiInquiryResponse [peripheralQualifier=0, peripheralDeviceType=0, removableMedia=false, spcVersion=6, responseDataFormat=2]
I/ScsiBlockDevice: Block size: 512
    Last block address: 31735807
E/ScsiBlockDevice: error transferring command, sending bulk only reset
E/ScsiBlockDevice: error transferring command, sending bulk only reset
E/ScsiBlockDevice: error transferring command, sending bulk only reset
E/UsbApiImgWriteService: Could't write image to Depau EtchDrive
    eu.depau.etchdroid.utils.exception.UsbWriteException: Write failed at block 1525760, 781.2 MB written. Error: java.io.IOException: Could not write to device, result == -1 errno 0 null
        at eu.depau.etchdroid.services.UsbApiWriteService.writeInputStream(UsbApiWriteService.kt:76)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeImage(UsbApiWriteService.kt:107)
        at eu.depau.etchdroid.services.UsbWriteService.onHandleIntent(UsbWriteService.kt:36)
        at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:78)
        at android.os.Handler.dispatchMessage(Handler.java:107)
        at android.os.Looper.loop(Looper.java:214)
        at android.os.HandlerThread.run(HandlerThread.java:67)
     Caused by: java.io.IOException: Could not write to device, result == -1 errno 0 null
        at com.github.mjdev.libaums.usb.JellyBeanMr2Communication.bulkOutTransfer(JellyBeanMr2Communication.kt:35)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferOneCommand(ScsiBlockDevice.kt:186)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:140)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.write(ScsiBlockDevice.kt:250)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeInputStream(UsbApiWriteService.kt:74)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeImage(UsbApiWriteService.kt:107) 
        at eu.depau.etchdroid.services.UsbWriteService.onHandleIntent(UsbWriteService.kt:36) 
        at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:78) 
        at android.os.Handler.dispatchMessage(Handler.java:107) 
        at android.os.Looper.loop(Looper.java:214) 
        at android.os.HandlerThread.run(HandlerThread.java:67) 
D/UsbMassStorageDevice: close device
D/UsbDeviceConnectionJNI: close

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

So, if this doesn't work, I think our last options are:

  • access UsbDeviceConnection.resetDevice() using reflection (it should do a port reset unless I'm missing something)
  • open the USB device, get the file descriptor, throw all the java crap away and use libusb

I'm aware of this policy, though trying is definitely easier than reimplementing the USB communication with raw libusb. If it doesn't work it should simply pretend the method does not exist, so handling that should be fine (in the sense that it won't get any worse than the current behavior).

Side note: it's quite tedious for me to develop changes and test them on EtchDroid as I have to rebuild the shim in the middle and stuff. @kuza2010, did the issue occur to you in the libaums demo app? Does somebody have some steps to reproduce it in the demo app?

@magnusja
Copy link
Owner

magnusja commented Jan 5, 2020

Hey @depau,

thanks a lot for testing. Well that is too bad :/ I will implement the first option, we can still think about the second one. We can also only move the reset then to native code. What essentially is happening is this: https://android.googlesource.com/platform/system/core/+/master/libusbhost/usbhost.c?autodive=0#682 This can be easily implement keeping the whole Kotlin (as of now :D) code!

@magnusja
Copy link
Owner

magnusja commented Jan 5, 2020

I pushed some more changes if someone wants to try again...

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

thanks a lot for testing. Well that is too bad :/ I will implement the first option, we can still think about the second one. We can also only move the reset then to native code. What essentially is happening is this: https://android.googlesource.com/platform/system/core/+/master/libusbhost/usbhost.c?autodive=0#682 This can be easily implement keeping the whole Kotlin (as of now :D) code!

Yeah, an IOCTL should be doable from Java/Kotlin.

Anyway, nope, it doesn't help:

I/UsbMassStorageDevice: MAX LUN 0
D/ScsiBlockDevice: inquiry response: ScsiInquiryResponse [peripheralQualifier=0, peripheralDeviceType=0, removableMedia=false, spcVersion=6, responseDataFormat=2]
I/ScsiBlockDevice: Block size: 512
    Last block address: 31735807
W/depau.etchdroi: JNI critical lock held for 65.871ms on Thread[5,tid=8545,Runnable,Thread*=0x6fa76c0c00,peer=0x12fc0040,"IntentService[UsbApiImgWriteService]"]
E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: sending bulk only mass storage request
W/AndroidUsbCommunication: sending clear feature halt
W/AndroidUsbCommunication: sending clear feature halt
E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: sending bulk only mass storage request
W/AndroidUsbCommunication: sending clear feature halt
W/AndroidUsbCommunication: sending clear feature halt
E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: sending bulk only mass storage request
W/AndroidUsbCommunication: sending clear feature halt
W/AndroidUsbCommunication: sending clear feature halt
E/UsbApiImgWriteService: Could't write image to Depau EtchDrive
    eu.depau.etchdroid.utils.exception.UsbWriteException: Write failed at block 0, 0.0 B written. Error: java.io.IOException: Could not write to device, result == -1 errno 0 null
        at eu.depau.etchdroid.services.UsbApiWriteService.writeInputStream(UsbApiWriteService.kt:76)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeImage(UsbApiWriteService.kt:107)
        at eu.depau.etchdroid.services.UsbWriteService.onHandleIntent(UsbWriteService.kt:36)
        at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:78)
        at android.os.Handler.dispatchMessage(Handler.java:107)
        at android.os.Looper.loop(Looper.java:214)
        at android.os.HandlerThread.run(HandlerThread.java:67)
     Caused by: java.io.IOException: Could not write to device, result == -1 errno 0 null
        at com.github.mjdev.libaums.usb.JellyBeanMr2Communication.bulkOutTransfer(JellyBeanMr2Communication.kt:35)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferOneCommand(ScsiBlockDevice.kt:191)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:142)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.write(ScsiBlockDevice.kt:255)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeInputStream(UsbApiWriteService.kt:74)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeImage(UsbApiWriteService.kt:107) 
        at eu.depau.etchdroid.services.UsbWriteService.onHandleIntent(UsbWriteService.kt:36) 
        at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:78) 
        at android.os.Handler.dispatchMessage(Handler.java:107) 
        at android.os.Looper.loop(Looper.java:214) 
        at android.os.HandlerThread.run(HandlerThread.java:67) 
D/UsbMassStorageDevice: close device
D/UsbDeviceConnectionJNI: close

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

BTW I'm going to implement the ioctl thing and see if it works.

@magnusja
Copy link
Owner

magnusja commented Jan 5, 2020

I actually implemented that already so dont bother. I forgot to push I guess, but will do now!

@magnusja
Copy link
Owner

magnusja commented Jan 5, 2020

aa50b40

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

Ah damn I reimplemented it in the meantime :/
I'll pull your changes and test it again.

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

Nope :(

D/UsbMassStorageDevice: setup device
I/UsbMassStorageDevice: MAX LUN 0
D/ScsiBlockDevice: inquiry response: ScsiInquiryResponse [peripheralQualifier=0, peripheralDeviceType=0, removableMedia=false, spcVersion=6, responseDataFormat=2]
I/ScsiBlockDevice: Block size: 512
    Last block address: 31735807
E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: sending bulk only mass storage request
W/AndroidUsbCommunication: sending clear feature halt
W/AndroidUsbCommunication: sending clear feature halt
W/AndroidUsbCommunication: Native reset
D/UsbDocumentProvider: detachDevice() UsbDevice[mName=/dev/bus/usb/001/002,mVendorId=3544,mProductId=12801,mClass=0,mSubclass=0,mProtocol=0,mManufacturerName=Depau,mProductName=EtchDrive,mVersion=11.00,mSerialNumberReader=android.hardware.usb.IUsbSerialReader$Stub$Proxy@a11f61b,mConfigurations=[
    UsbConfiguration[mId=1,mName=null,mAttributes=128,mMaxPower=50,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]]]]
E/UsbApiImgWriteService: Could't write image to Depau EtchDrive
    eu.depau.etchdroid.utils.exception.UsbWriteException: Write failed at block 0, 0.0 B written. Error: java.io.IOException: native reset unsuccessful!
        at eu.depau.etchdroid.services.UsbApiWriteService.writeInputStream(UsbApiWriteService.kt:76)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeImage(UsbApiWriteService.kt:107)
        at eu.depau.etchdroid.services.UsbWriteService.onHandleIntent(UsbWriteService.kt:36)
        at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:78)
        at android.os.Handler.dispatchMessage(Handler.java:107)
        at android.os.Looper.loop(Looper.java:214)
        at android.os.HandlerThread.run(HandlerThread.java:67)
     Caused by: java.io.IOException: native reset unsuccessful!
        at com.github.mjdev.libaums.usb.AndroidUsbCommunication.resetRecovery(AndroidUsbCommunication.kt:41)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:149)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.write(ScsiBlockDevice.kt:255)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeInputStream(UsbApiWriteService.kt:74)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeImage(UsbApiWriteService.kt:107) 
        at eu.depau.etchdroid.services.UsbWriteService.onHandleIntent(UsbWriteService.kt:36) 
        at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:78) 
        at android.os.Handler.dispatchMessage(Handler.java:107) 
        at android.os.Looper.loop(Looper.java:214) 
        at android.os.HandlerThread.run(HandlerThread.java:67) 
D/UsbMassStorageDevice: close device
E/UsbMassStorageDevice: could not release interface!
D/UsbDeviceConnectionJNI: close

Also after the "native reset" the USB does not show up any more when querying for USB devices. (which is good to know cause I might just reset the device after writing the image successfully, so people stop complaining that their USB drive is broken when Android says the filesystem is unsupported)

@magnusja
Copy link
Owner

magnusja commented Jan 5, 2020

Ah snap, that is a pity.

So this guy (https://raspberrypi.stackexchange.com/a/36664) says that we might wanna ignore the unsuccessful reset. Maybe you can comment this out (https://github.com/magnusja/libaums/pull/240/files#diff-c624845c950d217d9416054a1cb06616R41) and see what happens? Other than that I am unsure what might be worth trying next :/

@magnusja
Copy link
Owner

magnusja commented Jan 5, 2020

Might be also worth a try only doing this native reset instead of the bulk only reset and the clear feature halt.

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

I tested the code in that thread on my computer on a USB drive.

(Here's my adapted code)
#include <errno.h>
#include <stdlib.h>
#include <stdio.h>
#include <sys/ioctl.h>
#include <linux/usbdevice_fs.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>

int main(int argc, char **argv)
{
    char devicename[1024];
    const char *filename = devicename;
    int fd;

    if ( 2 > argc || 3 < argc ) {
        printf("Give USB device name as parameter\n");
        return 1;
    }

    if ( 2 == argc ) 
        filename = argv[1];
    else
        sprintf( devicename, "/dev/bus/usb/%s/%s", argv[1], argv[2] );

    printf( "Resetting USB device '%s'\n", filename );

    fd = open(filename, O_WRONLY);
    if (fd <= 0) {
        perror("USB device open failed");
        return 2;
    }
    if (ioctl((long) fd, USBDEVFS_RESET, 0) == -1) {
        // Don't care!  It usually does, when we need to reset it.
        perror("USBDEVFS_RESET device ioctl error");
        //exit(3);
    }
    close(fd);
    return 0;
}

Results: sometimes the ioctl succeeds and I get this:

[125565.446601] usb 2-1: reset SuperSpeed Gen 1 USB device number 5 using xhci_hcd

Sometimes it fails:

Resetting USB device '/dev/bus/usb/001/067'
USBDEVFS_RESET device ioctl error: No such device

and when that happens

[126888.902296] usb 1-1: USB disconnect, device number 67
[126889.025746] usb 2-1: new SuperSpeed Gen 1 USB device number 7 using xhci_hcd

Which makes me fear we need to move deviceConnection = usbManager.openDevice(usbDevice) etc from UsbMassStorageDevice to AndroidUsbCommunication, as in the second case we have to reopen it (hopefully we already have permissions).

I'm currently fighting with gradle, I'll see what I can do.

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

I'm noticing that, for whatever reason, I'm getting almost always successfully writes while back then I would only be able to write ~500MB before it would show the issue.

Anyway I was tired of not seeing errors so I built the utility for Android and used it to reset the USB drive while the app was writing, which triggered the new code of course.

I'm testing with a bunch of commits on top of your changes: https://github.com/Depau/libaums/tree/feature/bulk-only-reset

Kernel log with comments:

# Manually performed reset
[ 2483.339314] usb 1-1: reset high-speed USB device number 3 using xhci-hcd
[ 2483.463313] xhci-hcd xhci-hcd.0.auto: xHCI xhci_drop_endpoint called with disabled ep 0000000000000000
[ 2483.463362] xhci-hcd xhci-hcd.0.auto: xHCI xhci_drop_endpoint called with disabled ep 0000000000000000
[ 2483.480856] xhci-hcd xhci-hcd.0.auto: hcd->state:1
[ 2483.482825] usb-storage 1-1:1.0: USB Mass Storage device detected
[ 2483.487379] scsi host11: usb-storage 1-1:1.0
# Resets performed by the app
[ 2483.611162] usb 1-1: reset high-speed USB device number 3 using xhci-hcd
[ 2483.740874] xhci-hcd xhci-hcd.0.auto: xHCI xhci_drop_endpoint called with disabled ep 0000000000000000
[ 2483.740930] xhci-hcd xhci-hcd.0.auto: xHCI xhci_drop_endpoint called with disabled ep 0000000000000000
[ 2483.754864] xhci-hcd xhci-hcd.0.auto: hcd->state:1
[ 2484.982369] scsi 11:0:0:0: Direct-Access     Depau    EtchDrive        1100 PQ: 0 ANSI: 6
[ 2485.001798] sdg: sdg1 sdg2
[ 2487.262678] usb 1-1: usbfs: process 15663 (IntentService[U) did not claim interface 0 before use
[ 2487.372826] usb 1-1: reset high-speed USB device number 3 using xhci-hcd
[ 2487.500100] xhci-hcd xhci-hcd.0.auto: xHCI xhci_drop_endpoint called with disabled ep 0000000000000000
[ 2487.500169] xhci-hcd xhci-hcd.0.auto: xHCI xhci_drop_endpoint called with disabled ep 0000000000000000
[ 2487.508317] xhci-hcd xhci-hcd.0.auto: hcd->state:1
[ 2491.015012] usb 1-1: usbfs: process 15663 (IntentService[U) did not claim interface 0 before use
[ 2491.126074] usb 1-1: reset high-speed USB device number 3 using xhci-hcd
[ 2491.252629] xhci-hcd xhci-hcd.0.auto: xHCI xhci_drop_endpoint called with disabled ep 0000000000000000
[ 2491.252682] xhci-hcd xhci-hcd.0.auto: xHCI xhci_drop_endpoint called with disabled ep 0000000000000000
[ 2491.269768] xhci-hcd xhci-hcd.0.auto: hcd->state:1
[ 2494.777149] usb 1-1: usbfs: process 15663 (IntentService[U) did not claim interface 0 before use

All ioctls succeeded so it didn't act like the drive was reinserted:

E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: Native reset
W/AndroidUsbCommunication: ioctl returned true; errno 0 null; ignoring
E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: Native reset
W/AndroidUsbCommunication: ioctl returned true; errno 0 null; ignoring
E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: Native reset
W/AndroidUsbCommunication: ioctl returned true; errno 0 null; ignoring
E/UsbApiImgWriteService: Could't write image to Depau EtchDrive
    eu.depau.etchdroid.utils.exception.UsbWriteException: Write failed at block 161792, 82.8 MB written. Error: java.io.IOException: Could not write to device, result == -1 errno 0 null
        at eu.depau.etchdroid.services.UsbApiWriteService.writeInputStream(UsbApiWriteService.kt:76)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeImage(UsbApiWriteService.kt:107)
        at eu.depau.etchdroid.services.UsbWriteService.onHandleIntent(UsbWriteService.kt:36)
        at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:76)
        at android.os.Handler.dispatchMessage(Handler.java:106)
        at android.os.Looper.loop(Looper.java:193)
        at android.os.HandlerThread.run(HandlerThread.java:65)
     Caused by: java.io.IOException: Could not write to device, result == -1 errno 0 null
        at com.github.mjdev.libaums.usb.JellyBeanMr2Communication.bulkOutTransfer(JellyBeanMr2Communication.kt:35)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferOneCommand(ScsiBlockDevice.kt:170)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:142)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.write(ScsiBlockDevice.kt:255)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeInputStream(UsbApiWriteService.kt:74)
        at eu.depau.etchdroid.services.UsbApiWriteService.writeImage(UsbApiWriteService.kt:107) 
        at eu.depau.etchdroid.services.UsbWriteService.onHandleIntent(UsbWriteService.kt:36) 
        at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:76) 
        at android.os.Handler.dispatchMessage(Handler.java:106) 
        at android.os.Looper.loop(Looper.java:193) 
        at android.os.HandlerThread.run(HandlerThread.java:65) 
D/UsbMassStorageDevice: close device
E/UsbMassStorageDevice: could not release interface!
D/UsbDeviceConnectionJNI: close
D/UsbApiImgWriteService: Written 0 bytes to Depau EtchDrive using API
W/System: A resource failed to call close. 

I'll try moving the opening code inside the communication class, so the USB connection can eventually be reopened after reset.

@depau
Copy link
Collaborator

depau commented Jan 5, 2020

It works! The sequence reset -> close -> open seems to do it. I was able to reset the device multiple times while it was writing, libaums would handle it gracefully by performing the recovery procedure.

I re-dumped the image from the USB drives and checksums were correct 🎉

At some point while testing my injected ioctl failed, though, so the device showed up as a new device. This probably needs to be handled at a higher level, like a physical reconnection.

EDIT:
nevermind, I tried on my other device and this happens:

E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: Native reset
W/AndroidUsbCommunication: ioctl returned true; errno 0 null; ignoring
E/AndroidUsbCommunication: could not release interface!
D/UsbDeviceConnectionJNI: close
D/AndroidUsbCommunication: setup device
E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: Native reset
W/AndroidUsbCommunication: ioctl returned true; errno 0 null; ignoring
E/AndroidUsbCommunication: could not release interface!
D/UsbDeviceConnectionJNI: close
D/AndroidUsbCommunication: setup device
E/ScsiBlockDevice: error transferring command, sending bulk only reset
W/AndroidUsbCommunication: Native reset
W/AndroidUsbCommunication: ioctl returned true; errno 0 null; ignoring
E/AndroidUsbCommunication: could not release interface!
D/UsbDeviceConnectionJNI: close
D/AndroidUsbCommunication: setup device

I can't get the kernel logs from this one as it's not rooted, so I have to do that first.

@magnusja
Copy link
Owner

magnusja commented Jan 6, 2020

Hey @depau

thanks a lot for your help and all the debugging! I guess you could call that progress at least :D If it is working reliably on one of your devices I guess it till makes sense merging this.

Let me know if you know something more about the failing device. Thanks!

@depau
Copy link
Collaborator

depau commented Jan 6, 2020

I'm currently not able to root it for whatever reason I'm not aware of. I'll try it again on QEMU and see if I'm able to reproduce it there. If not, I don't think I'll be able to work on it any more for this month :/

@depau
Copy link
Collaborator

depau commented Jan 6, 2020

Alright, it looks like trying over and over to reset the device works some times, I saw it resume writing after one or two attempts. In one test it halted a few times and recovered again.

Sometimes though, the reset ioctl fails and the USB device "disappears".

I think that for the time being the changes can be merged; in the worst case the USB device will "disappear". In the best case the communication will resume.

Ultimately, looking at libusb code, I think that eventually wrapping it would solve lot of issues and that it might be worth spending time on that. They seem to have a lot of checks for "suspiciously specific" issues and comparing libusb and the Android usbhost lib it looks like Android is taking a lot of shortcuts (see libusb's reset device vs Android's for example)

@magnusja
Copy link
Owner

magnusja commented Jan 8, 2020

Hey @depau

so I merged and released a new version to see if people still open bug reports regarding this error :D

In general I like the idea with libusb, but I am not sure how this is affecting the license as LGPL is quite restrictive I think. In addition all the Linux fs implementations are under GPL which would make closed apps using lbaums impossible unfortunately.

@kuza2010 @mannyzhao please try latest version

@depau
Copy link
Collaborator

depau commented Jan 10, 2020

java.lang.IllegalStateException: This should never happen.

Whoops I think that's my fault. Fixed in #243.

I am using libusb in this branch #242
Maybe you can test it.

That was quick :) I'll try it tonight

@depau
Copy link
Collaborator

depau commented Jan 10, 2020

@kuza2010 Have you ever seen it recover sometimes after an IO error? I.e. you see a bunch of those Trying to reset the device messages and then it actually recovers after that instead of crashing?

@kuza2010
Copy link
Author

Hey @depau

During the copying process, the recovery mechanism can be called successfully several times. I saw that the implemented recover mechanism works as intended and after that copy process was successfully completed.
But in another case, the recovery mechanism will crash. As I said earlier, the result can be successful or unsuccessful.

@depau
Copy link
Collaborator

depau commented Jan 11, 2020

During the copying process, the recovery mechanism can be called successfully several times. I saw that the implemented recover mechanism works as intended and after that copy process was successfully completed.
But in another case, the recovery mechanism will crash. As I said earlier, the result can be successful or unsuccessful.

At least we can't tell for sure it does help sometimes, it's not completely useless. Hopefully we'll get more consistent results with the libusb implementation, but this should already be good news for anybody who can't/doesn't want to use LGPL code.

@magnusja
Copy link
Owner

@kuza2010
Copy link
Author

@magnusja
I tried your remark, how it described here: https://github.com/magnusja/libaums/tree/develop/libusbcommunication
Unfortunately, it does not work for me.

com.myapp.test E/LIBAUMS: AbstractUsbWriteOperation: some IOException
    java.io.IOException: libusb returned -7 in bulk out transfer
        at me.jahnen.libaums.libusbcommunication.LibusbCommunication.bulkOutTransfer(LibusbCommunication.kt:59)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferOneCommand(ScsiBlockDevice.kt:218)
        at com.github.mjdev.libaums.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:144)
        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.FAT.alloc$libaums_release(FAT.kt:261)
        at com.github.mjdev.libaums.fs.fat32.FatDirectory.createFile(FatDirectory.kt:313)
        at com.github.mjdev.libaums.fs.fat32.FatDirectory.createFile(FatDirectory.kt:36)
        .....

full: https://pastebin.com/T3fcnqmi

@magnusja
Copy link
Owner

Hey @kuza2010

thanks a lot for testing.

Arghh that is annoying. Which device is this? The Samsung one I assume? Or does this apply to Samsung and the Xiaomi one?
Does this work if you copy one large 2 GB file instead of multiple small ones?

@depau Which devices did you test under Android 9?

@depau
Copy link
Collaborator

depau commented Jan 13, 2020

That's the same error I get on QEMU.

BTW you may also want to test the latest version of EtchDroid, I shipped it with the new libusb implementation.

@depau Which devices did you test under Android 9?

Xiaomi Mi 9 Lite with Pixel Experience GSI, OnePlus 3T with LineageOS MicroG, Android x86 on QEMU with a real USB drive passed-through.

@kuza2010
Copy link
Author

@magnusja

The latest version was tested only with Samsung.
Tomorrow I will continue my test and let you know results. Thanks!

@kuza2010
Copy link
Author

kuza2010 commented Jan 14, 2020

@magnusja
It was tested on Xiaomi now. Unfortunately, the recovery mechanism still didn't work as well; (

During the process of copying one huge file (1 and 2 Gb), the recovery mechanism was never been called. I tried about 10 attempts per each file :|

Host:

  • android version 9 Samsung Galaxy S10e
  • android version 8 Xiaomi Redmi 5 Plus

@magnusja
Copy link
Owner

Okay I see, thanks a lot for testing.

Maybe I can optimize the copy of multiple files somehow so that it results in fewer small writes. Can you maybe provide the code copying the 1000 files?

@kuza2010
Copy link
Author

kuza2010 commented Jan 15, 2020

It is very kind of your side!

I think it is real, but it takes time because I need to solve a few problems.
I hope that I can prepare the code until next week.

@kuza2010
Copy link
Author

kuza2010 commented Jan 21, 2020

Hey @magnusja
I am so sorry for my delay.

So, please find simple snippets below:

  1. FileSystemService class: https://pastebin.com/Cfb5cB8m
@Override
public synchronized InputStream getInputStream(UsbMassStorageDevice device, FileItem fileItem)
        throws USBException, IOException {

    Timber.tag(TAG).d("getInputStream: open stream %s ...", fileItem.getPath());
    FileSystem fs = getFs(device);
    UsbFile rootDir = fs.getRootDirectory();

	// getRelativePath return /folder/file.txt for path /Usb_prefix/folder/file.txt
    UsbFile srcFile = rootDir.search(getRelativePath(fs, fileItem.getPath()));
    if (srcFile == null)
        throw new USBException(USBErrorCode.FILE_NOT_FOUND);

    return UsbFileStreamFactory.createBufferedInputStream(srcFile, fs);
}

@Override
public synchronized OutputStream getOutputStream(UsbMassStorageDevice device, FileItem fileItem)
        throws IOException, USBException {

    Timber.tag(TAG).d("getOutputStream: open stream %s ...", fileItem.getPath());
    FileSystem fs = getFs(device);
    UsbFile rootDir = fs.getRootDirectory();

    UsbFile srcFile = rootDir.search(getRelativePath(fs, fileItem.getPath()));
    if (srcFile != null) 
        throw new USBException(USBErrorCode.FILE_EXISTS);

	//create parent folder for srcFile
    UsbFile srcFileParentFolder = mkDirs(device, constructParentFileItem(fileItem));
    srcFile = srcFileParentFolder.createFile(fileItem.getName());

    return UsbFileStreamFactory.createBufferedOutputStream(srcFile, fs);
}
  1. UsbReadOperation class: https://pastebin.com/rkHYCXUY
void doRead() throws IOException {
    if (this.state.compareAndSet(State.NEW, State.RUNNING))
		// some checks before read and create Output Stream
        if (!prepareForRead()) return;

    if ((this.state.get() == State.RUNNING)
            || this.state.compareAndSet(State.SUSPENDED, State.RUNNING)) {

        try {
			// Integer.maxValue
            int executeCount = weight;

            do {
                if (failedBytes != null) {
                    boolean isOfferSucceed;
                    if (failedBytes == Constants.EOF) {
                        isOfferSucceed = offerEOF();
                    } else {
                        isOfferSucceed = offerNextBlock(failedBytes, failedBytes.length);
                    }
                    if (isOfferSucceed) {
                        failedBytes = null;
                    } else {
						//suspend operation because failed bytes did not insert into queue
                        suspend();
                    }
                } else {
					//read from Is next readBlockSize bytes
                    byte[] contents = new byte[readBlockSize];
                    int readBytes = inputStream.read(contents);
                    boolean isEOF = checkIsEndOfFile(readBytes);

                    if (isEOF) {
                        Timber.tag(TAG).i("Achieve end of file %s", srcFileItem.getName());
						//insert EOF = {}
                        offerEOF();
                    } else {
                        if (readBytes < contents.length) {
                            byte[] bytesCopied = Arrays.copyOf(contents, readBytes);
                            offerNextBlock(bytesCopied, readBytes);
                        } else {
                            offerNextBlock(contents, readBytes);
                        }
                    }
                }
                executeCount--;
            } while (isExitCondition(executeCount));
            state.compareAndSet(State.RUNNING, State.SUSPENDED);
        } finally {
            if (getState() == State.COMPLETED)
                closeStreams();
        }
    }
}

// Offer EOF = {} into blocking queuq
private boolean offerEOF() {
    boolean isAddSucceed = blockingQueue.offer(Constants.EOF);
    if (isAddSucceed) {
        Timber.tag(TAG).i("Read completed for the file %s", srcFileItem.getUri());
        state.set(State.COMPLETED);
        delegate.onReadSuccess();
    } else {
        failedBytes = Constants.EOF;
        suspend();
    }
    return isAddSucceed;
}

// Offer next read data into blocking queue
boolean offerNextBlock(byte[] contents, int readBytes) {
    boolean isAddSucceed = blockingQueue.offer(contents);
    if (isAddSucceed) {
		//delegate on progress changed will call
        publishReadProgress(readBytes);
    } else {
        failedBytes = contents;
        suspend();
    }
    return isAddSucceed;
}

void createStream() throws IOException, USBException {
	// FileSystemService.getInputStream will be called
    inputStream = api.getFileSystemService().getInputStream(usbDevice, srcFileItem);
    // you should read and write in multiples of chunk size 
	// return device.partitions.get(0).getFileSystem().getChunkSize()
    int chunkSize = storageLocation.getChunkSize();

	// readblockSize = minimum of (maximum of chunk size and file size) and 
	// integer value from dividing the buffer size by chunk si
    readBlockSize = (int) Math.min(Math.max(chunkSize, srcFileItem.getLength()),
            preferences.getBufferSize() / chunkSize * chunkSize);
    Timber.tag(TAG).d("createStream: IS successfully created, readBlockSize = %s", readBlockSize);
}

void closeStreams() throws IOException {
    if (inputStream != null) {
        inputStream.close();
        inputStream = null;
    }
}

@Override
public boolean suspend() {
    return this.state.compareAndSet(State.RUNNING, State.SUSPENDED);
}
  1. UsbWriteOperation class: https://pastebin.com/qBFY6WTc
protected void doWrite() throws IOException {
    if (this.state.compareAndSet(State.NEW, State.RUNNING)) {
		// some checks before write and create Output Stream
        if (!prepareForWrite()) {
            return;
        }
    }
    if ((this.state.get() == State.RUNNING)
            || this.state.compareAndSet(State.SUSPENDED, State.RUNNING)) {
        byte[] nextByte;
        try {
			// Integer.maxValue
            int executeCount = weight;
            do {
				// retrieves next block of data from queue
                nextByte = blockingQueue.poll();
                if (nextByte == null) {
					//suspend because blocking queue is empty
                    suspend();
                    break;
                }
                if (isPoissonPill(nextByte)) {
                    state.set(State.COMPLETED);
                    Timber.tag(TAG).i("Write completed for the file %s", destFile.getPath());
                    break;
                } else {
					// write data to device
                    outputStream.write(nextByte);
                    publishProgress(nextByte.length);
                    executeCount--;
                }
            } while (isExitCondition(executeCount));
            state.compareAndSet(State.RUNNING, State.SUSPENDED);
        } finally {
            if (State.COMPLETED == state.get()) {
                closeStreams();
                delegate.onWriteSuccess();
            }
        }
    }
}

// check EOF
private boolean isPoissonPill(byte[] nextByte) {
    return nextByte == Constants.EOF;
}

void createStream() throws USBException, IOException {
	// FileSystemService.getOutputStream will be called
    outputStream = api.getFileSystemService().getOutputStream(usbDevice, destFile);
    file = api.getFileSystemService().getUsbFile(usbDevice, destFile);
}

private void closeStreams() {
    try {
        if (outputStream != null) {
            outputStream.close();
            outputStream = null;
        }
    } catch (IOException e) {
        e.printStackTrace();
    }
}

@Override
public boolean suspend() {
    return this.state.compareAndSet(State.RUNNING, State.SUSPENDED);
}

Some details with can help to understand how it works:

  • FileSystemService class use to create Input and Output stream
  • Read operation stores read bytes inside blocking queue
  • Write operation takes bytes from blocking queue

Feel free to ask questions.

@magnusja
Copy link
Owner

Hey there,

thanks for the code. What you might want to try, which definitely results in fewer writes is instead of using the buffered stream factory just do:

return new BufferedInputStream(new UsbFileInputStream(file), 32000) // or maybe 16000

Another thing you might want to try is to set the length of the file you are copying first. This will allocate memory for the file in one run and increases performance. Otherwise you are always switching between writing the actual file and allocating new space in the FAT. So please do something like usbFile.setLength(srcFile.getLength()) before copying the streams.

@kuza2010
Copy link
Author

kuza2010 commented Jan 22, 2020

Hey @magnusja

I implemented your advice above and tried a few copying attempts. But I still observe the same issue :( For tests, I used implementation 'me.jahnen:libaums:0.7.5' libaums version.
Positive changes:

  • it worked more stable (4/5 attempts were successful);
  • I feel, that setting usb file length before writing gave us a small performance increase.

UPD:
Today I again tried the advice above. Today I used a mass storage device with chunk size = 64kb. I am still facing the issue.

Thanks

@kuza2010
Copy link
Author

kuza2010 commented Jan 31, 2020

Hey @magnusja

I tested it again with some new phones. Test data: about 1000 mixed size/type files (total size 2 Gb).
For my tests I used the next phones list:

  • Moto g5s (xt1794) Android 8.1
  • Xiaomi Redmi 5 Plus Android 8.1
  • Samsung Galaxy S10e Android 9.0

And tests results very strange and unpredictable. For example, on Moto device I can copy all files successfully (5/5). But if I use Xiaomi/Samsung I can't copy the same folder (0/5), in these cases I get
java.io.IOException: Could not write to device, result == -1 errno 0 null after copy at about 200 - 300 files.
I'm not sure, but maybe the issue depends on the device hardware?

@kuza2010
Copy link
Author

Hey there,

I can't find any other ways to solve this problem.
I am still facing the issue. Any updates which can help.

@magnusja
Copy link
Owner

Unfortunately I am out of ideas :/

I would suggest that you try to debug that on your own and let us know if you have any further insights.
Another option is to switch to standard Android file API if your device supports mounting of USB drives out of the box. (Which most of the modern devices should I think)

@depau
Copy link
Collaborator

depau commented May 13, 2020

Sorry for not showing up for a while, before resuming not showing up for another few months I'd like to add that switching to libusb did reduce by a lot the number of bug reports/bad reviews on the Play Store for EtchDroid.

Now I'm basically only getting bad reviews because people flashed a Windows ISO and [surprised pikachu face] the BIOS says "no bootable medium found" (though I literally added a huge message "WINDOWS ISOs NOT SUPPORTED") or because they have no idea how filesystems work and they think the USB drive is broken when Android/Windows tells them they need to format it before using it.

The issue is definitely not solved yet since it does still occur sometimes on real devices, it still occurs 100% times on Qemu, and it doesn't occur with the proprietary app. I hope I'll have some time in the summer to finish up the Qemu instrumented tests and see if we can shed a light on it.

@magnusja
Copy link
Owner

Sorry for not showing up for a while, before resuming not showing up for another few months I'd like to add that switching to libusb did reduce by a lot the number of bug reports/bad reviews on the Play Store for EtchDroid.

Great to here from you and the improved reviews! :) Hope you are staying safe.

Now I'm basically only getting bad reviews because people flashed a Windows ISO and [surprised pikachu face] the BIOS says "no bootable medium found" (though I literally added a huge message "WINDOWS ISOs NOT SUPPORTED") or because they have no idea how filesystems work and they think the USB drive is broken when Android/Windows tells them they need to format it before using it.

Well people, huh? :D

The issue is definitely not solved yet since it does still occur sometimes on real devices, it still occurs 100% times on Qemu, and it doesn't occur with the proprietary app. I hope I'll have some time in the summer to finish up the Qemu instrumented tests and see if we can shed a light on it.

Thanks a lot for your commitment! What proprietary app do you mean? USB Media Explorer, formerly Nexus Media Importer or Total Commander?

@depau
Copy link
Collaborator

depau commented May 16, 2020

Thanks a lot for your commitment! What proprietary app do you mean? USB Media Explorer, formerly Nexus Media Importer or Total Commander?

I don't remember right now, I think we talked about it in the Qemu thread :) I remember it was a proprietary plugin for a file manager, so probably total commander

@salovapes
Copy link

Hello! I have scroll here and trying to find the problem! I have tried to transfer windows 10 from my phone to my USB drive because I need to install windows on my PC because it's corrupt and it worked first but my PC wanned not to accept it haha! So now I have delete everything on the PC and now the app wouldnt accept it! And it's the code this quote start with .. 1 errno 0 null have you guys figured out?

@depau
Copy link
Collaborator

depau commented Aug 13, 2020

Hello! I have scroll here and trying to find the problem! I have tried to transfer windows 10 from my phone to my USB drive because I need to install windows on my PC because it's corrupt and it worked first but my PC wanned not to accept it haha! So now I have delete everything on the PC and now the app wouldnt accept it! And it's the code this quote start with .. 1 errno 0 null have you guys figured out?

image

@depau
Copy link
Collaborator

depau commented Aug 13, 2020

@kuza2010 Can you please try again with the latest commits from develop?

You can use JitPack for a quick test:

implementation 'com.github.magnusja:libaums:develop-SNAPSHOT'

Also you should be able to run the instrumented tests, can you see if they work? Pull the develop branch and run ./gradlew androidtests:connectedAndroidTest, or just run them from Android Studio from the androidtests module.

@kuza2010
Copy link
Author

@depau at the moment it's impossible for me to test it with the last commit.
But as soon as I have the opportunity I will do it and provide the result, thanks.

@kuza2010
Copy link
Author

kuza2010 commented Oct 9, 2020

Hello, fellas!
I have tried @depau's advice and use:

implementation 'com.github.magnusja:libaums:develop-SNAPSHOT'

For tests, I used the same phones set and mass storages.
The result below:

@depau
Copy link
Collaborator

depau commented Oct 9, 2020

Hello, fellas!
I have tried @depau's advice and use:

implementation 'com.github.magnusja:libaums:develop-SNAPSHOT'

For tests, I used the same phones set and mass storages.
The result below:

* Copy 2Gb from internal memory to USB (details: https://pastebin.com/RM6MdudA)
  `java.io.IOException: Could not claim interface, errno: 0 null`

[...] AndroidUsbCommunication [...]

Can you try the libusb implementation? If you can't use it in production due to licensing issues, can you at least test it with libusb and let us know if it works with it? Libusb gives better error messages.

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

No branches or pull requests

5 participants