search

JeffLIrion / adb_shell

A Python implementation of ADB with shell and FileSync functionality.
Apache License 2.0
543 stars 60 forks source link

`device.stat()` times out over USB transport in 0.3.2 #155

Closed maybe-sybr closed 3 years ago

maybe-sybr commented 3 years ago

Description

Run device.stat("/any/path/which/exists") with a USB transport device and observe that it now times out. It seems like something in the new code merged to fix #152 must be wrong.

Log

Test code, with a USB ADB device plugged in:

import logging
import pathlib

import adb_shell.adb_device
import adb_shell.auth.sign_pythonrsa
import adb_shell.transport.usb_transport

logging.basicConfig(level=logging.DEBUG)

adbkey_path = pathlib.Path("~/.android/adbkey").expanduser()
signer = adb_shell.auth.sign_pythonrsa.PythonRSASigner.FromRSAKeyPath(str(adbkey_path))

handle = adb_shell.transport.usb_transport.UsbTransport.find_adb()
device = adb_shell.adb_device.AdbDeviceUsb(port_path=handle.port_path)

device.connect([signer])
try:
    device.shell("echo hello world")
    device.stat("/")
finally:
    device.close()

Output:

DEBUG:adb_shell.adb_device:bulk_write(24): b'CNXN\x00\x00\x00\x01\x00\x00\x10\x00\x0c\x00\x00\x00>\x04\x00\x00\xbc\xb1\xa7\xb1'
DEBUG:adb_shell.adb_device:bulk_write(12): b'host::karma\x00'
DEBUG:adb_shell.adb_device:bulk_read(24): b'CLSE\xbb\x01\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xbc\xb3\xac\xba'
DEBUG:adb_shell.adb_device:bulk_read(24): b'AUTH\x01\x00\x00\x00\x00\x00\x00\x00\x14\x00\x00\x00D\x08\x00\x00\xbe\xaa\xab\xb7'
DEBUG:adb_shell.adb_device:bulk_read(20): b'\x12\xfb\xa0\x02\xc9JZ\xfe)E\xec|\x00\x1b0w\x18\xe8^4'
DEBUG:adb_shell.adb_device:bulk_write(24): b'AUTH\x02\x00\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00M\x80\x00\x00\xbe\xaa\xab\xb7'
DEBUG:adb_shell.adb_device:bulk_write(256): b'0\x05\x97\x16\xe2\x81F\xb2\x9d\xa5U\xbc\xffP\xf0\nH\r\x95\x054\x86\xe3eX\x06\xbb\x08\xb8\x9fV\xe0d\xb9t\x13\x87R\x8a\xda\xe2\xe6\xfa\xdb.\n\xa1\xe0\x04\x1f\xab&%/\xf5\x1e\'\xf4\x1a\xffx\xb0\x15\xcd\xbb\xa7\xb7\xf9\xc5\xca\xc2\xa9T\x01\xc2\x14\xaf\xf79\x1a\xed\xa4\xe4\xb9\xb0\xa9\'\x0b.P\x95\xb4UK?\xbeF\x88\xf1\xe9\x0fr"\xe8\x14\xa5t\xd2\xac\xbc\xac\xca\xa6\xe17Bt\xb8\xcbd\xc7\xaeO\x10\x1a=v\xf2N\\\xdf\x8d\xaa\xd5\x14\xf3Ei\xb4\xcb\x13\x7f\x1e3\xc1\x9cG\x1fI\xeeM\xc4\x94w\xe3\x1c\x8d\xa5\x03\x81d\x1bM\xfeYn\xb3n\xd65\x9b\x94\x02\xdese\xd8\xe9\xfa\x8b\xe6G\xa7\x04\x05\xf1\x8b\x0fK\xd5i\xb8B\xb7\x81\xaft@\xa3\xf1L,\xaddR\x9f\x9dB\t\x9f\x00\xc2t\x19azlN\xe0\x93A\xc6\xf2(\x9f\x00E9\xb8p\x1b\xcd\x82\xcb\xe3j\x7f\x85\x84\xa2\xa4\xb2\xc1q=\x98\x07u\xe1\xb0\xcc\xafy\xddMM'
DEBUG:adb_shell.adb_device:bulk_read(24): b'CNXN\x01\x00\x00\x01\x00\x00\x10\x00\xde\x00\x00\x00^T\x00\x00\xbc\xb1\xa7\xb1'
DEBUG:adb_shell.adb_device:bulk_read(222): b'device::ro.product.name=x1sxx;ro.product.model=SM-G980F;ro.product.device=x1s;features=sendrecv_v2_brotli,remount_shell,sendrecv_v2,abb_exec,fixed_push_mkdir,fixed_push_symlink_timestamp,abb,shell_v2,cmd,ls_v2,apex,stat_v2'
DEBUG:adb_shell.adb_device:bulk_write(24): b'OPEN\x01\x00\x00\x00\x00\x00\x00\x00\x17\x00\x00\x00m\x08\x00\x00\xb0\xaf\xba\xb1'
DEBUG:adb_shell.adb_device:bulk_write(23): b'shell:echo hello world\x00'
DEBUG:adb_shell.adb_device:bulk_read(24): b'OKAY\xbc\x01\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
DEBUG:adb_shell.adb_device:bulk_read(24): b'WRTE\xbc\x01\x00\x00\x01\x00\x00\x00\x0c\x00\x00\x00f\x04\x00\x00\xa8\xad\xab\xba'
DEBUG:adb_shell.adb_device:bulk_read(12): b'hello world\n'
DEBUG:adb_shell.adb_device:bulk_write(24): b'OKAY\x01\x00\x00\x00\xbc\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
DEBUG:adb_shell.adb_device:bulk_read(24): b'CLSE\xbc\x01\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xbc\xb3\xac\xba'
DEBUG:adb_shell.adb_device:bulk_write(24): b'CLSE\x01\x00\x00\x00\xbc\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xbc\xb3\xac\xba'
DEBUG:adb_shell.adb_device:bulk_write(24): b'OPEN\x01\x00\x00\x00\x00\x00\x00\x00\x06\x00\x00\x00\xf7\x01\x00\x00\xb0\xaf\xba\xb1'
DEBUG:adb_shell.adb_device:bulk_write(6): b'sync:\x00'
DEBUG:adb_shell.adb_device:bulk_read(24): b'CLSE\xbc\x01\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xbc\xb3\xac\xba'
DEBUG:adb_shell.adb_device:bulk_read(24): b'OKAY\xbd\x01\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
DEBUG:adb_shell.adb_device:bulk_write(24): b'WRTE\x01\x00\x00\x00\xbd\x01\x00\x00\t\x00\x00\x00l\x01\x00\x00\xa8\xad\xab\xba'
DEBUG:adb_shell.adb_device:bulk_write(9): bytearray(b'STAT\x01\x00\x00\x00/')
DEBUG:adb_shell.adb_device:bulk_read(24): b'OKAY\xbd\x01\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
DEBUG:adb_shell.adb_device:bulk_read(24): b'WRTE\xbd\x01\x00\x00\x01\x00\x00\x00\x10\x00\x00\x00\x96\x04\x00\x00\xa8\xad\xab\xba'
DEBUG:adb_shell.adb_device:bulk_read(16): b'STAT\xedA\x00\x00\x00\x10\x00\x00\xf0\x88[I'
DEBUG:adb_shell.adb_device:bulk_write(24): b'OKAY\x01\x00\x00\x00\xbd\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
Traceback (most recent call last):
  File "/work/.venv/lib64/python3.8/site-packages/adb_shell/transport/usb_transport.py", line 278, in bulk_read
    return bytes(self._transport.bulkRead(self._read_endpoint, numbytes, timeout=self._timeout_ms(transport_timeout_s)))
  File "/work/.venv/lib64/python3.8/site-packages/usb1/__init__.py", line 1429, in bulkRead
    transferred = self._bulkTransfer(endpoint, data, length, timeout)
  File "/work/.venv/lib64/python3.8/site-packages/usb1/__init__.py", line 1377, in _bulkTransfer
    mayRaiseUSBError(libusb1.libusb_bulk_transfer(
  File "/work/.venv/lib64/python3.8/site-packages/usb1/__init__.py", line 127, in mayRaiseUSBError
    __raiseUSBError(value)
  File "/work/.venv/lib64/python3.8/site-packages/usb1/__init__.py", line 119, in raiseUSBError
    raise __STATUS_TO_EXCEPTION_DICT.get(value, __USBError)(value)
usb1.USBErrorTimeout: LIBUSB_ERROR_TIMEOUT [-7]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "stat.py", line 19, in <module>
    device.stat("/")
  File "/work/.venv/lib64/python3.8/site-packages/adb_shell/adb_device.py", line 711, in stat
    _, (mode, size, mtime), _ = self._filesync_read([constants.STAT], adb_info, filesync_info, read_data=False)
  File "/work/.venv/lib64/python3.8/site-packages/adb_shell/adb_device.py", line 1107, in _filesync_read
    data = self._filesync_read_buffered(size, adb_info, filesync_info)
  File "/work/.venv/lib64/python3.8/site-packages/adb_shell/adb_device.py", line 1142, in _filesync_read_buffered
    _, data = self._read_until([constants.WRTE], adb_info)
  File "/work/.venv/lib64/python3.8/site-packages/adb_shell/adb_device.py", line 918, in _read_until
    cmd, remote_id2, local_id2, data = self._read(expected_cmds, adb_info)
  File "/work/.venv/lib64/python3.8/site-packages/adb_shell/adb_device.py", line 866, in _read
    msg = self._transport.bulk_read(constants.MESSAGE_SIZE, adb_info.transport_timeout_s)
  File "/work/.venv/lib64/python3.8/site-packages/adb_shell/transport/usb_transport.py", line 280, in bulk_read
    raise exceptions.UsbReadFailedError('Could not receive data from %s (timeout %sms)' % (self.usb_info, self._timeout_ms(transport_timeout_s)), e)
adb_shell.exceptions.UsbReadFailedError: Could not receive data from [3, 8, 4, 2, 3] RF8N20P1Y4B (timeout 10000ms): LIBUSB_ERROR_TIMEOUT [-7]
maybe-sybr commented 3 years ago

Here's what it should look like, with a0e1d4c reverted:

DEBUG:adb_shell.adb_device:bulk_read(24): b'CNXN\x01\x00\x00\x01\x00\x00\x10\x00\xde\x00\x00\x00^T\x00\x00\xbc\xb1\xa7\xb1'
DEBUG:adb_shell.adb_device:bulk_read(222): b'device::ro.product.name=x1sxx;ro.product.model=SM-G980F;ro.product.device=x1s;features=sendrecv_v2_brotli,remount_shell,sendrecv_v2,abb_exec,fixed_push_mkdir,fixed_push_symlink_timestamp,abb,shell_v2,cmd,ls_v2,apex,stat_v2'
DEBUG:adb_shell.adb_device:bulk_write(24): b'OPEN\x01\x00\x00\x00\x00\x00\x00\x00\x17\x00\x00\x00m\x08\x00\x00\xb0\xaf\xba\xb1'
DEBUG:adb_shell.adb_device:bulk_write(23): b'shell:echo hello world\x00'
DEBUG:adb_shell.adb_device:bulk_read(24): b'OKAY\n\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
DEBUG:adb_shell.adb_device:bulk_read(24): b'WRTE\n\x00\x00\x00\x01\x00\x00\x00\x0c\x00\x00\x00f\x04\x00\x00\xa8\xad\xab\xba'
DEBUG:adb_shell.adb_device:bulk_read(12): b'hello world\n'
DEBUG:adb_shell.adb_device:bulk_write(24): b'OKAY\x01\x00\x00\x00\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
DEBUG:adb_shell.adb_device:bulk_read(24): b'CLSE\n\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xbc\xb3\xac\xba'
DEBUG:adb_shell.adb_device:bulk_write(24): b'CLSE\x01\x00\x00\x00\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xbc\xb3\xac\xba'
DEBUG:adb_shell.adb_device:bulk_write(24): b'OPEN\x01\x00\x00\x00\x00\x00\x00\x00\x06\x00\x00\x00\xf7\x01\x00\x00\xb0\xaf\xba\xb1'
DEBUG:adb_shell.adb_device:bulk_write(6): b'sync:\x00'
DEBUG:adb_shell.adb_device:bulk_read(24): b'CLSE\n\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xbc\xb3\xac\xba'
DEBUG:adb_shell.adb_device:bulk_read(24): b'OKAY\x0b\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
DEBUG:adb_shell.adb_device:bulk_write(24): b'WRTE\x01\x00\x00\x00\x0b\x00\x00\x00\t\x00\x00\x00l\x01\x00\x00\xa8\xad\xab\xba'
DEBUG:adb_shell.adb_device:bulk_write(9): bytearray(b'STAT\x01\x00\x00\x00/')
DEBUG:adb_shell.adb_device:bulk_read(24): b'OKAY\x0b\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
DEBUG:adb_shell.adb_device:bulk_read(24): b'WRTE\x0b\x00\x00\x00\x01\x00\x00\x00\x10\x00\x00\x00\x96\x04\x00\x00\xa8\xad\xab\xba'
DEBUG:adb_shell.adb_device:bulk_read(16): b'STAT\xedA\x00\x00\x00\x10\x00\x00\xf0\x88[I'
DEBUG:adb_shell.adb_device:bulk_write(24): b'OKAY\x01\x00\x00\x00\x0b\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6'
DEBUG:adb_shell.adb_device:bulk_write(24): b'CLSE\x01\x00\x00\x00\x0b\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xbc\xb3\xac\xba'
DEBUG:adb_shell.adb_device:bulk_read(24): b'CLSE\x0b\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xbc\xb3\xac\xba'

Edit: On master, interestingly the timeout does not occur if you stat a path which does not exist. It doesn't seem to want anything after getting the STAT back and is happy to move on after sending OKAY and then closing the connection. I've amended the issue description accordingly.

JeffLIrion commented 3 years ago

Thanks for the detailed info! I think this will fix it: https://github.com/JeffLIrion/adb_shell/pull/156

Could you please let me know.

maybe-sybr commented 3 years ago

I think that'd fix it (will confirm in a moment) but I reckon we should also fix the following assumption:

https://github.com/JeffLIrion/adb_shell/blob/7bc1a2183a7e497436edb598ee2f1dc170864197/adb_shell/adb_device.py#L1104-L1106

The size field being the last element of the received message format is only valid for messages carrying DENTs, DATA, or one of the status types like OKAY/FAIL. I'm referring to the definition for union syncmsg at [0]. STAT results are thus being interpreted as the size for a subsequent read which is what's blocking. Here's output with some extra logging:

DEBUG:adb_shell.adb_device:bulk_write(6): b'sync:\x00'
DEBUG:adb_shell.adb_device:Waiting to see [b'OKAY']
DEBUG:adb_shell.adb_device:bulk_read(24): b"OKAY'\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6"
DEBUG:adb_shell.adb_device:Finished _read_length -> bytearray(b'')
DEBUG:adb_shell.adb_device:bulk_write(24): b"WRTE\x01\x00\x00\x00'\x00\x00\x00\x12\x00\x00\x00\xd8\x04\x00\x00\xa8\xad\xab\xba"
DEBUG:adb_shell.adb_device:bulk_write(18): bytearray(b'STAT\n\x00\x00\x00/data/data')
DEBUG:adb_shell.adb_device:Waiting to see [b'OKAY']
DEBUG:adb_shell.adb_device:bulk_read(24): b"OKAY'\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6"
DEBUG:adb_shell.adb_device:Finished _read_length -> bytearray(b'')
DEBUG:adb_shell.adb_device:Need 16 bytes, have 0
DEBUG:adb_shell.adb_device:Waiting to see [b'WRTE']
DEBUG:adb_shell.adb_device:bulk_read(24): b"WRTE'\x00\x00\x00\x01\x00\x00\x00\x10\x00\x00\x00\xcb\x05\x00\x00\xa8\xad\xab\xba"
DEBUG:adb_shell.adb_device:Awaiting 16 more bytes
DEBUG:adb_shell.adb_device:bulk_read(16): b'STAT\xf9A\x00\x00\x00\xd0\x00\x00\xe8\xa1\x9c`'
DEBUG:adb_shell.adb_device:Finished _read_length -> bytearray(b'STAT\xf9A\x00\x00\x00\xd0\x00\x00\xe8\xa1\x9c`')
DEBUG:adb_shell.adb_device:bulk_write(24): b"OKAY\x01\x00\x00\x00'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xb0\xb4\xbe\xa6"
DEBUG:adb_shell.adb_device:About to read 1620877800 (command_id: b'STAT')
DEBUG:adb_shell.adb_device:Need 1620877800 bytes, have 0
DEBUG:adb_shell.adb_device:Waiting to see [b'WRTE']
Traceback (most recent call last):
...

I think what we should do in addition to what you already have in #156 would be to only set the size var (L1106) and call self._filesync_read_buffered() again for the sync reply messages which need that done. That'll make sure that regardless of what value read_data has, we'll always handle messages properly.

In fact, that change might even remove the need for read_data entirely since it only seems to be used as a shortcut for STATs :) If it were meaningful to do a PUSH/PULL/LIST and then not read_data, we could make that available to users in the public methods, but since the sync service on the device will send data regardless, it'll need to be drained by something on the client side...

Edit: That PR does fix the issue - viable fix :) Thanks for pushing it up so quickly!

[0] https://android.googlesource.com/platform/system/adb/+/refs/heads/master/file_sync_service.h

JeffLIrion commented 3 years ago

I pushed some changes to my pull request. I removed the read_data parameter from _filesync_read() and instead defined that variable inside the method as simply

read_data = command_id != constants.STAT

If there are other commands for which we shouldn't read data, they can easily be added to that check, but for now it looks like that's the only one.

I'll tag you as a reviewer on the pull request, please take a look when you get a chance.

Edit: it looks like I can't tag you as a reviewer... but please look it over.

JeffLIrion commented 3 years ago

Closed via https://github.com/JeffLIrion/adb_shell/pull/156