Potential bug in ScsiBlockDevice.requestSense()

[depau]

I was working on EtchDroid and I noticed this exception:

eu.depau.etchdroid.utils.exception.InitException: Initialization failed
    at eu.depau.etchdroid.service.WorkerService$onStartCommand$2.invokeSuspend(WorkerService.kt:310)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
    at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:115)
    at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:103)
    at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:793)
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:697)
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:684)
Caused by: java.lang.IllegalArgumentException: newLimit > capacity: (36 > 18)
    at java.nio.Buffer.createLimitException(Buffer.java:366)
    at java.nio.Buffer.limit(Buffer.java:340)
    at java.nio.ByteBuffer.limit(ByteBuffer.java:863)
    at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.transferOneCommand(ScsiBlockDevice.kt:280)
    at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.requestSense(ScsiBlockDevice.kt:222)
    at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.handleCommandResult(ScsiBlockDevice.kt:207)
    at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.transferCommand(ScsiBlockDevice.kt:155)
    at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.transferCommandWithoutDataPhase(ScsiBlockDevice.kt:199)
    at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.initAttempt(ScsiBlockDevice.kt:115)
    at me.jahnen.libaums.core.driver.scsi.ScsiBlockDevice.init(ScsiBlockDevice.kt:83)
    at eu.depau.etchdroid.massstorage.EtchDroidUsbMassStorageDevice.setupDevice(EtchDroidUsbMassStorageDevice.kt:213)
    at eu.depau.etchdroid.massstorage.EtchDroidUsbMassStorageDevice.init(EtchDroidUsbMassStorageDevice.kt:183)
    at eu.depau.etchdroid.service.WorkerService$onStartCommand$2.invokeSuspend(WorkerService.kt:306)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) 
    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108) 
    at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:115) 
    at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:103) 
    at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584) 
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:793) 
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:697) 
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:684) 

This is not a big deal for EtchDroid since I've implemented failure recovery: it will ask the user to reconnect the USB drive and keep going. However I'm puzzled by what might be going on. I'm not sure how to reproduce this consistently since a command failure needs to happen before the sense data is requested. Maybe we could record a USB communication log, then mock the Android USB API similarly to what libfprint does to implement device tests? Anyway I'm digressing, I'll open another issue to track that.

Anyway, the culprit seems to be in ScsiBlockDevice.kt:222:

    private fun requestSense() {
        val inBuffer = ByteBuffer.allocate(18)
        val sense = ScsiRequestSense(inBuffer.array().size.toByte(), lun = lun)
        when (val status = transferOneCommand(sense, inBuffer)) {
		    // ...

and in ScsiBlockDevice.kt:269:

        var transferLength = command.dCbwDataTransferLength
        inBuffer.limit(inBuffer.position() + transferLength)

AFAIU command.dCbwDataTransferLength should end up being the argument to the ScsiRequestSense ctor, inBuffer.array().size.toByte() which should be 18. That means the only way the result of the expression can be 36 is if inBuffer.position() is somehow == inBuffer.capacity(), which doesn't make a lot of sense since according to the docs a fresh ByteBuffer should have the position set to zero.

Do you have any ideas?

[magnusja]

Yeah as you describe it it sounds very weird. Not sure if enlarging the buffer would be a quick fix?

Maybe there is a bug that the val = inBuffer gets alatered somewhere further down the road? EDIT: does not look like it. This is also not the retry of the sense command so that maybe some buffer is not reset properly in the retry phase? (Think 18+18 = 36)

[letsfire]

var transferLength = command.dCbwDataTransferLength
inBuffer.limit(inBuffer.position() + transferLength)

var read = 0
if (transferLength > 0) {

    if (command.direction == Direction.IN) {
        do {
            read += usbCommunication.bulkInTransfer(inBuffer)
            if (command.bCbwDynamicSize) {
                transferLength = command.dynamicSizeFromPartialResponse(inBuffer)
                // This line serves what purpose? When I commented it out, the error did not occur
                // inBuffer.limit(inBuffer.position() + transferLength)
            }
        } while (read < transferLength)

        if (read != transferLength) {
            throw IOException("Unexpected command size (" + read + ") on response to "
                    + command)
        }
    } else {
        written = 0
        do {
            written += usbCommunication.bulkOutTransfer(inBuffer)
        } while (written < transferLength)

        if (written != transferLength) {
            throw IOException("Could not write all bytes: $command")
        }
    }
}