edl icon indicating copy to clipboard operation
edl copied to clipboard
verified publisher icon bkerler

USBTimeoutError(60, b'Unknown error') <class 'usb.core.USBTimeoutError'> 60 - regression on FreeBSD between 31d71f88 and 0cc421a

Open saper opened this issue 4 years ago • 2 comments

I am trying to talk to Nokia 8110 4G using FreeBSD using edl with master at https://github.com/bkerler/edl/commit/0cc421a16079a2f33a9b1e1c1fe9816ad10327ab or 3.52.1 or 3.1 releases:

Script started on Sun Nov 21 23:31:49 2021
Command: ktrace -f /tmp/edl-master-0cc421a.trace python edl --debugmode printgpt
Qualcomm Sahara / Firehose Client V3.53 (c) B.Kerler 2018-2021.
main - Trying with no loader given ...
main - Waiting for the device
UsbClass
UsbClass - [LIB]: [95m  CONFIGURATION 1: 2 mA ====================================
   bLength              :    0x9 (9 bytes)
   bDescriptorType      :    0x2 Configuration
   wTotalLength         :   0x20 (32 bytes)
   bNumInterfaces       :    0x1
   bConfigurationValue  :    0x1
   iConfiguration       :    0x0 
   bmAttributes         :   0x80 Bus Powered
   bMaxPower            :    0x1 (2 mA)
    INTERFACE 0: Vendor Specific ===========================
     bLength            :    0x9 (9 bytes)
     bDescriptorType    :    0x4 Interface
     bInterfaceNumber   :    0x0
     bAlternateSetting  :    0x0
     bNumEndpoints      :    0x2
     bInterfaceClass    :   0xff Vendor Specific
     bInterfaceSubClass :   0xff
     bInterfaceProtocol :   0xff
     iInterface         :    0x0 
      ENDPOINT 0x81: Bulk IN ===============================
       bLength          :    0x7 (7 bytes)
       bDescriptorType  :    0x5 Endpoint
       bEndpointAddress :   0x81 IN
       bmAttributes     :    0x2 Bulk
       wMaxPacketSize   :  0x200 (512 bytes)
       bInterval        :    0x0
      ENDPOINT 0x1: Bulk OUT ===============================
       bLength          :    0x7 (7 bytes)
       bDescriptorType  :    0x5 Endpoint
       bEndpointAddress :    0x1 OUT
       bmAttributes     :    0x2 Bulk
       wMaxPacketSize   :  0x200 (512 bytes)
       bInterval        :    0x0[0m
UsbClass
UsbClass - [LIB]: [95mDetaching kernel driver[0m
UsbClass
UsbClass - [LIB]: [95mNo kernel driver supported: [Errno None] b'Unknown error'[0m
UsbClass
UsbClass - [LIB]: [95mDetaching kernel driver[0m
UsbClass
UsbClass - [LIB]: [95mNo kernel driver supported: [Errno None] b'Unknown error'[0m
main - Device detected :)
UsbClass
UsbClass - [LIB]: [95mconnect:0x80[0m
USBTimeoutError(60, b'Unknown error') <class 'usb.core.USBTimeoutError'> 60

Command exit status: 0
Script done on Sun Nov 21 23:31:51 2021

edl.py in its old revison (at https://github.com/bkerler/edl/commit/31d71f886cba78bae610d563737edac395fda739) mostly works as far as USB concerned (XML error is not relevant to this case, but the communication in both Sahara and Firehose protocols works fine).

Script started on Sun Nov 21 23:32:27 2021
Command: ktrace -f /tmp/edl-master-31d71f88.trace python edl.py -printgpt

Qualcomm Sahara / Firehose Client (c) B.Kerler 2018-2019.


Trying with loaders in Loader directory ...
Waiting for the device
Device detected :)
Mode detected: Firehose
TargetName=MSM8909
MemoryName=eMMC
Version=1

Reading from physical partition 0, sector 0, sectors 32
Traceback (most recent call last):
  File "edl.py", line 419, in <module>
    main()
  File "edl.py", line 197, in main
    data = fh.cmd_read_buffer(args.lun, 0, 0x4000 // cfg.SECTOR_SIZE_IN_BYTES)
  File "/usr/home/saper/sw/edl/Library/firehose.py", line 241, in cmd_read_buffer
    rsp=self.xmlsend(data)
  File "/usr/home/saper/sw/edl/Library/firehose.py", line 73, in xmlsend
    resp = self.xml.getresponse(data)
  File "/usr/home/saper/sw/edl/Library/firehose.py", line 16, in getresponse
    tree = ET.fromstring(line, parser=parser)
  File "/usr/local/lib/python3.8/xml/etree/ElementTree.py", line 1320, in XML
    parser.feed(text)
xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 1, column 5

Command exit status: 1
Script done on Sun Nov 21 23:32:31 2021

The timeout problem is not a real timeout, the error is returned immediately; attempting to increase it does not mostly change things.

Since troubleshooting it requires wading through USB libraries, I have also traced all system calls issued by edl.py. All versions of edl tested in the same virtualenv set up with requirements.txt of the master version - https://github.com/bkerler/edl/commit/0cc421a16079a2f33a9b1e1c1fe9816ad10327ab).

I have published detailed logs and traces at https://github.com/saper/edl-timeout-issue

saper avatar Nov 21 '21 23:11 saper

USB connection using master:

 56875 python3.8 CALL  ioctl(0x8,USB_FS_OPEN,0x7fffffffc6d8)
 56875 python3.8 RET   ioctl 0
 56875 python3.8 CALL  ioctl(0x8,USB_FS_START,0x7fffffffc720)
 56875 python3.8 RET   ioctl 0
 56875 python3.8 CALL  ioctl(0x8,USB_FS_COMPLETE,0x7fffffffc728)
 56875 python3.8 RET   ioctl -1 errno 16 Device busy
 56875 python3.8 CALL  poll(0x7fffffffc748,0x1,0xffffffff)
 56875 python3.8 RET   poll 1
 56875 python3.8 CALL  ioctl(0x8,USB_FS_COMPLETE,0x7fffffffc728)
 56875 python3.8 RET   ioctl 0
 56875 python3.8 CALL  ioctl(0x8,USB_FS_COMPLETE,0x7fffffffc728)
 56875 python3.8 RET   ioctl -1 errno 16 Device busy
 56875 python3.8 CALL  write(0x1,0x8022cd000,0x4c)
 56875 python3.8 GIO   fd 1 wrote 76 bytes
       "USBTimeoutError(60, b'Unknown error') <class 'usb.core.USBTimeoutError'> 60
       "
 56875 python3.8 RET   write 76/0x4c

working case:

 57557 python3.8 CALL  ioctl(0x5,USB_FS_OPEN,0x7fffffffcc78)
 57557 python3.8 RET   ioctl 0
 57557 python3.8 CALL  ioctl(0x5,USB_FS_START,0x7fffffffccc0)
 57557 python3.8 RET   ioctl 0
 57557 python3.8 CALL  ioctl(0x5,USB_FS_COMPLETE,0x7fffffffccc8)
 57557 python3.8 RET   ioctl -1 errno 16 Device busy
 57557 python3.8 CALL  poll(0x7fffffffcce8,0x1,0xffffffff)
 57557 python3.8 RET   poll 1
 57557 python3.8 CALL  ioctl(0x5,USB_FS_COMPLETE,0x7fffffffccc8)
 57557 python3.8 RET   ioctl 0
 57557 python3.8 CALL  ioctl(0x5,USB_FS_COMPLETE,0x7fffffffccc8)
 57557 python3.8 RET   ioctl -1 errno 16 Device busy
 57557 python3.8 CALL  ioctl(0x5,USB_FS_OPEN,0x7fffffffcc78)
 57557 python3.8 RET   ioctl 0
 57557 python3.8 CALL  ioctl(0x5,USB_FS_START,0x7fffffffccc0)
 57557 python3.8 RET   ioctl 0
 57557 python3.8 CALL  ioctl(0x5,USB_FS_COMPLETE,0x7fffffffccc8)
 57557 python3.8 RET   ioctl -1 errno 16 Device busy
 57557 python3.8 CALL  poll(0x7fffffffcce8,0x1,0xffffffff)
 57557 python3.8 RET   poll 1
 57557 python3.8 CALL  ioctl(0x5,USB_FS_COMPLETE,0x7fffffffccc8)
 57557 python3.8 RET   ioctl 0
 57557 python3.8 CALL  ioctl(0x5,USB_FS_COMPLETE,0x7fffffffccc8)
 57557 python3.8 RET   ioctl -1 errno 16 Device busy
 57557 python3.8 CALL  ioctl(0x5,USB_FS_START,0x7fffffffccc0)
 57557 python3.8 RET   ioctl 0
 57557 python3.8 CALL  ioctl(0x5,USB_FS_COMPLETE,0x7fffffffccc8)
 57557 python3.8 RET   ioctl -1 errno 16 Device busy
 57557 python3.8 CALL  poll(0x7fffffffcce8,0x1,0xffffffff)
 57557 python3.8 RET   poll 1
 57557 python3.8 CALL  ioctl(0x5,USB_FS_COMPLETE,0x7fffffffccc8)
 57557 python3.8 RET   ioctl 0
 57557 python3.8 CALL  ioctl(0x5,USB_FS_COMPLETE,0x7fffffffccc8)
 57557 python3.8 RET   ioctl -1 errno 16 Device busy

saper avatar Nov 21 '21 23:11 saper

Not sure what might cause this. I'm going to test the script with my Nokia 8110 4G.

bkerler avatar Dec 05 '21 13:12 bkerler