crash when calling init method of UsbMassStorageDevice.

[melonsherbet]

Problem

crash when setup device

Expected behavior

succed to get the root directory

Actual behavior

crash when calling init method of UsbMassStorageDevice.

Stacktrace of Excpetion

FATAL EXCEPTION: main
Process: com.aispeech.dui.dds.usbotgdemo, PID: 1252
java.lang.RuntimeException: Error receiving broadcast Intent { act=com.newsmy.farosh.USB_PERMISSION flg=0x10 hwFlg=0x100 (has extras) } in com.aispeech.dui.dds.usbotgdemo.MainActivity$1@e688b84
	at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$getRunnable$0$LoadedApk$ReceiverDispatcher$Args(LoadedApk.java:1796)
	at android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA.run(Unknown Source:2)
	at android.os.Handler.handleCallback(Handler.java:900)
	at android.os.Handler.dispatchMessage(Handler.java:103)
	at android.os.Looper.loop(Looper.java:219)
	at android.app.ActivityThread.main(ActivityThread.java:8668)
	at java.lang.reflect.Method.invoke(Native Method)
	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:513)
	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1109)
Caused by: java.lang.IllegalArgumentException
	at java.nio.Buffer.limit(Buffer.java:290)
	at java.nio.ByteBuffer.limit(ByteBuffer.java:818)
	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.transferOneCommand(ScsiBlockDevice.kt:270)
	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:154)
	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.initAttempt(ScsiBlockDevice.kt:105)
	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.init(ScsiBlockDevice.kt:83)
	at me.jahnen.libaums.core.UsbMassStorageDevice.setupDevice(UsbMassStorageDevice.kt:138)
	at me.jahnen.libaums.core.UsbMassStorageDevice.init(UsbMassStorageDevice.kt:100)
	at com.aispeech.dui.dds.usbotgdemo.MainActivity.setupDevice(MainActivity.java:118)
	at com.aispeech.dui.dds.usbotgdemo.MainActivity.access$000(MainActivity.java:25)
	at com.aispeech.dui.dds.usbotgdemo.MainActivity$1.onReceive(MainActivity.java:42)
	at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$getRunnable$0$LoadedApk$ReceiverDispatcher$Args(LoadedApk.java:1786)
	at android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA.run(Unknown Source:2) 
	at android.os.Handler.handleCallback(Handler.java:900) 
	at android.os.Handler.dispatchMessage(Handler.java:103) 
	at android.os.Looper.loop(Looper.java:219) 
	at android.app.ActivityThread.main(ActivityThread.java:8668) 
	at java.lang.reflect.Method.invoke(Native Method) 
	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:513) 
	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1109) 

Code where problem occurs

discoverDevice

	usbManager = (UsbManager) getSystemService(Context.USB_SERVICE);
	massStorageDevices = UsbMassStorageDevice.getMassStorageDevices(this);
	if (massStorageDevices.length == 0){
		return;
	}
	usbDevice = intent.getParcelableExtra(UsbManager.EXTRA_DEVICE);

	Log.i("MainActivity :: " , "usbManager.hasPermission == " + usbManager.hasPermission(usbDevice));

	if (usbDevice != null && usbManager.hasPermission(usbDevice)){
		setupDevice();
	}else {
		PendingIntent pendingIntent = PendingIntent.getBroadcast(this
				, 0, new Intent(ACTION_USB_PERMISSION), 0);
		usbManager.requestPermission(massStorageDevices[0].getUsbDevice(), pendingIntent);
	}
}

setup Device

private void setupDevice() {
	try {
		Log.e("MainActivity", "massStorageDevices size: " + massStorageDevices.length);
		massStorageDevices[0].init();
		Log.i("MainActivity", "massStorageDevices init success ");
		// we always use the first partition of the device
		FileSystem currentFs = massStorageDevices[0].getPartitions().get(0).getFileSystem();
		UsbFile root = currentFs.getRootDirectory();
		textView.setText(root.getName());

	} catch (IOException e) {
		Log.i("MainActivity", "setupDevice: exception == "+ e.getMessage());
	}
}

[magnusja]

Hmm can you tell me what the value of position and transfer length are, here: https://github.com/magnusja/libaums/blob/develop/libaums/src/main/java/me/jahnen/libaums/core/driver/scsi/ScsiBlockDevice.kt#L270

[xzeman43]

Hello Magnus, seems like I have a similar issue. In my case, it dies when the transfer length and position are both 18 (it's not right on the first call of transferOneCommand, but the third? one). The code can be traced up to line 280 (as indicated in the error log below) and then jump straight to the Illegal argument exception...

java.lang.IllegalArgumentException
13:48:12.269  W  	at java.nio.Buffer.limit(Buffer.java:290)
13:48:12.275  W  	at java.nio.ByteBuffer.limit(ByteBuffer.java:818)
13:48:12.281  W  	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.transferOneCommand(ScsiBlockDevice.kt:280)
13:48:12.286  W  	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.requestSense(ScsiBlockDevice.kt:222)
13:48:12.300  W  	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.handleCommandResult(ScsiBlockDevice.kt:207)
13:48:12.305  W  	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:155)
13:48:12.310  W  	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.transferCommandWithoutDataPhase(ScsiBlockDevice.kt:199)
13:48:12.314  W  	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.initAttempt(ScsiBlockDevice.kt:115)
13:48:12.318  W  	at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.init(ScsiBlockDevice.kt:83)
13:48:12.322  W  	at me.jahnen.libaums.core.UsbMassStorageDevice.setupDevice(UsbMassStorageDevice.kt:138)
13:48:12.327  W  	at me.jahnen.libaums.core.UsbMassStorageDevice.init(UsbMassStorageDevice.kt:100)
13:48:12.331  W  	at cz.test.MainActivity.readOutCurrSettings(MainActivity.java:1110)
13:48:12.335  W  	at cz.test.MainActivity$9.onReceive(MainActivity.java:1031)
13:48:12.339  W  	at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$getRunnable$0$LoadedApk$ReceiverDispatcher$Args(LoadedApk.java:1646)
13:48:12.343  W  	at android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA.run(Unknown Source:2)
13:48:12.347  W  	at android.os.Handler.handleCallback(Handler.java:883)
13:48:12.354  W  	at android.os.Handler.dispatchMessage(Handler.java:100)
13:48:12.356  W  	at android.os.Looper.loop(Looper.java:237)
13:48:12.358  W  	at android.app.ActivityThread.main(ActivityThread.java:8167)
13:48:12.359  W  	at java.lang.reflect.Method.invoke(Native Method)
13:48:12.361  W  	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:496)
13:48:12.363  W  	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1100)

Other than that, the issue emerges after I call device.init(). The device is retrieved by UsbMassStorageDevice.getMassStorageDevices and interestingly enough, for one USB flash drive it failed, but other it went through...

Not sure if it will help or not, but these are the test devices USBDevices read out by the library:

THIS is the one that is not working correctly

found usb device:
/dev/bus/usb/001/003=UsbDevice[mName=/dev/bus/usb/001/003,mVendorId=1423,mProductId=25479,mClass=0,mSubclass=0,mProtocol=0,mManufacturerName=USB,mProductName=Mass Storage,mVersion=1.03,mSerialNumberReader=android.hardware.usb.IUsbSerialReader$Stub$Proxy@f2660a0,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]]]]
14:13:00.067  I  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]]
14:13:00.068  I  Found usb endpoint: UsbEndpoint[mAddress=1,mAttributes=2,mMaxPacketSize=512,mInterval=0]
14:13:00.069  I  Found usb endpoint: UsbEndpoint[mAddress=130,mAttributes=2,mMaxPacketSize=512,mInterval=0]

This one initializes ok

found usb device: /dev/bus/usb/001/002=UsbDevice[mName=/dev/bus/usb/001/002,mVendorId=2385,mProductId=5658,mClass=0,mSubclass=0,mProtocol=0,mManufacturerName=Kingston,mProductName=DataTraveler 410,mVersion=1.00,mSerialNumberReader=android.hardware.usb.IUsbSerialReader$Stub$Proxy@e7e6579,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=129,mAttributes=2,mMaxPacketSize=512,mInterval=0]
                 UsbEndpoint[mAddress=2,mAttributes=2,mMaxPacketSize=512,mInterval=0]]]]
14:10:53.709  I  Found usb interface: UsbInterface[mId=0,mAlternateSetting=0,mName=null,mClass=8,mSubclass=6,mProtocol=80,mEndpoints=[
                 UsbEndpoint[mAddress=129,mAttributes=2,mMaxPacketSize=512,mInterval=0]
                 UsbEndpoint[mAddress=2,mAttributes=2,mMaxPacketSize=512,mInterval=0]]
14:10:53.710  I  Found usb endpoint: UsbEndpoint[mAddress=129,mAttributes=2,mMaxPacketSize=512,mInterval=0]
14:10:53.710  I  Found usb endpoint: UsbEndpoint[mAddress=2,mAttributes=2,mMaxPacketSize=512,mInterval=0]

If there will be anything you need from me just let me know I will try to provide as much information as I can....

[magnusja]

So your device fails when trying to test if the unit is ready. The OP has the problem that the ScsiInquiry does not work.

So afaik testing if the unit is ready, has no data phase. But your device seems to respond with some more data.

[xzeman43]

Then I am sorry for exploiting this thread. However, it is interesting that both devices are standard USB disks formatted to the same filesystem. I will try to dig deeper and find out why they do no behave the same.

[xzeman43]

So your device fails when trying to test if the unit is ready. The OP has the problem that the ScsiInquiry does not work.

So afaik testing if the unit is ready, has no data phase. But your device seems to respond with some more data.

Hello, so quick update on the issue you described. For whatever reason I did not see it straight away but it seems that the error occurs if the device.init() happens too fast after the device attachment. When I launch the procedure straight from UsbManager.ACTION_USB_DEVICE_ATTACHED callback without any delay, 99/100 attempts fail on the java.lang.IllegalArgumentException .However, when I introduce a slight delay (one sec seems stable) after the USB attach event, it works flawlessly. Maybe it will be a pleasant update to have a method that will be checking for this specific issue - it seems like after the USB attach broadcast, there is still some initialization running in the background that messes up with your library.

[viktor76525]

Hello, I also bumped into this regression. The workaround is to wait 900+ms before calling init.
It only happens on certain USB drives, not sandisk, mostly older usb 2 and no-name ones.
It was ok on 0.9.1, couldn't get intermediate versions to build due to some dependency issues, and then it is in both 0.9.4 and 0.10.0.

[xzeman43]

Hello, I also bumped into this regression. The workaround is to wait 900+ms before calling init. It only happens on certain USB drives, not sandisk, mostly older usb 2 and no-name ones. It was ok on 0.9.1, couldn't get intermediate versions to build due to some dependency issues, and then it is in both 0.9.4 and 0.10.0.

Yes, that seems in line with my observations. But still, from time to time it breaks the connection with the device and it has to be reconnected. So the solution was quick and easy to implement, but somehow its not 100% bulletproof.