search

pyocd / pyOCD

Open source Python library for programming and debugging Arm Cortex-M microcontrollers
https://pyocd.io
Apache License 2.0
1.13k stars 483 forks source link

v0.33.0 USB Error: Operation timed out #1322

Closed BlokhinDima closed 2 years ago

BlokhinDima commented 2 years ago

Instantly have this exception when trying to use v0.33.0. For e.g. if i try pyocd list command. My proggramer is ST-link. OS Windows 10. (As i understand i don't need libusb-1.0.dll in Python folder, but i've tried to add it anyway. Doesn't work.)

Everything is good with v0.32.3 and libusb-1.0.dll installed in Python 3.10.1 folder.

0007003 C USB Error: [Errno 10060] Operation timed out [__main__]

Please ask, if you need more information.

flit commented 2 years ago

Thanks for reporting the issue! The change to use a copy of libusb automatically provisioned as a dependency (via libusb-package) of pyocd is new in v0.33, so I'm not totally surprised there are issues even with all the testing I did. Thanks also for confirming that v0.32.3 works for you.

First questions:

Thanks! I will also try to reproduce.

vacagonzalo commented 2 years ago

Thanks for reporting the issue! The change to use a copy of libusb automatically provisioned as a dependency (via libusb-package) of pyocd is new in v0.33, so I'm not totally surprised there are issues even with all the testing I did. Thanks also for confirming that v0.32.3 works for you.

First questions:

* What version of libusb did you install that works? (libusb-package currently contains version libusb 1.0.24.)

* Is your Python installation 32-bit or 64-bit?

* Would you mind running `pyocd list -vv -L "*trace=debug"` and providing the output here?

Thanks! I will also try to reproduce.

Hello, I cannot run pyocd list. Note: I cp udev rules.

USB Error: [Errno 110] Operation timed out

My groups:

administrador : administrador adm dialout cdrom sudo dip plugdev lpadmin lxd sambashare docker

Debug msg:

0000382 D setting log level debug for ['pyocd.trace', 'pyocd.coresight.ap.trace', 'pyocd.utility.notification.trace', 'pyocd.coresight.dap.trace', 'pyocd.flash.flash.trace', 'pyocd.debug.semihost.trace', 'pyocd.gdbserver.packet_io.trace', 'pyocd.probe.pydapaccess.interface.hidapi_backend.trace', 'pyocd.probe.pydapaccess.interface.pyusb_backend.trace', 'pyocd.probe.pydapaccess.interface.pyusb_v2_backend.trace', 'pyocd.probe.pydapaccess.interface.pywinusb_backend.trace', 'pyocd.probe.pydapaccess.dap_access_cmsis_dap.trace', 'pyocd.probe.cmsis_dap_probe.trace', 'pyocd.probe.jlink_probe.trace', 'pyocd.probe.tcp_client_probe.trace', 'pyocd.probe.stlink.usb.trace', 'pyocd_pemicro.pemicro_probe.trace', 'pyocd.gdbserver.gdbserver.trace', 'pyocd.probe.tcp_probe_server.trace'] [__main__]
0000383 D Project directory: /home/administrador/Documentos [session]
0000391 D [Errno 13] Access denied (insufficient permissions) while trying to interrogate a USB device (VID=046d PID=c52b). This can probably be remedied with a udev rule. See <https://github.com/pyocd/pyOCD/tree/master/udev> for help. [pyusb_backend]
0000391 D [Errno 13] Access denied (insufficient permissions) while trying to interrogate a USB device (VID=1bcf PID=2b98). This can probably be remedied with a udev rule. See <https://github.com/pyocd/pyOCD/tree/master/udev> for help. [pyusb_backend]
0000406 D [Errno 13] Access denied (insufficient permissions) while trying to interrogate a USB device (VID=046d PID=c52b). This can probably be remedied with a udev rule. See <https://github.com/pyocd/pyOCD/tree/master/udev> for help. [pyusb_v2_backend]
0000406 D [Errno 13] Access denied (insufficient permissions) while trying to interrogate a USB device (VID=1bcf PID=2b98). This can probably be remedied with a udev rule. See <https://github.com/pyocd/pyOCD/tree/master/udev> for help. [pyusb_v2_backend]
0000422 D   USB CMD> (16) f5 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000423 D   USB IN < (req 2 bytes) [usb]
0000423 D   USB IN < (2) 01 00 [usb]
0000423 D   USB CMD> (16) f1 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000423 D   USB IN < (req 6 bytes) [usb]
0000424 D   USB IN < (6) 29 5b 83 04 4b 37 [usb]
0000424 D STLink probe 066DFF485152728381124434 firmware version: V2J37M27 [stlink]
0000424 D   USB CMD> (16) f7 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000424 D   USB IN < (req 8 bytes) [usb]
0000424 D   USB IN < (8) f3 05 00 00 0d 08 00 00 [usb]
0000424 D   USB CMD> (16) f2 56 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000425 D   USB IN < (req 36 bytes) [usb]
0000425 D   USB IN < (36) 80 00 30 37 39 36 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 4e 4f 44 45 5f 46 34 32 39 5a 49 00 [usb]
0000425 D   USB CMD> (16) f5 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0001426 C USB Error: [Errno 110] Operation timed out [__main__]

My machine:

OS: Ubuntu 20.04.3 LTS x86_64 Host: Vostro 3405 1.4.6 Kernel: 5.13.0-27-generic Shell: bash 5.0.17 Resolution: 1366x768, 1600x900 CPU: AMD Ryzen 5 3450U with Radeon Vega Mobile Gfx (8) @ 2.100GHz GPU: AMD ATI 04:00.0 Picasso

flit commented 2 years ago

@vacagonzalo Interesting, you get the same error as on @BlokhinDima does on Windows. Thanks for providing the debug trace and system details.

I've retested on Ubuntu 18.04.6 and 20.04.3 (same kernel, etc as you), and Windows 10 1909 (all x86_64). On Windows, I tested with git-bash, cmd.exe, and PS. Of course, everything works fine. 😔

One notable difference with my test systems is that they are all VMs running in VMWare Fusion Pro 12.2.1 on a 2018 MacBook Pro (x86_64) under macOS 11.6.2. I don't have a "real" Windows or Linux machine.

My current plan is to release v0.33.1 soon that will revert the inclusion of libusb-package (and thus requires users to manually install libusb on non-Linux systems), then continue to try to reproduce and debug. The main focus will be on Windows, since that's the system where installing libusb is the most confusing for users. (For Linux, the use of the libusb-package version of libusb was primarily to ensure consistency.)

I may be able to put together a test script, and will report back to this issue to request help running it on affected systems.

vacagonzalo commented 2 years ago

@vacagonzalo Interesting, you get the same error as on @BlokhinDima does on Windows. Thanks for providing the debug trace and system details.

I've retested on Ubuntu 18.04.6 and 20.04.3 (same kernel, etc as you), and Windows 10 1909 (all x86_64). On Windows, I tested with git-bash, cmd.exe, and PS. Of course, everything works fine. pensive

One notable difference with my test systems is that they are all VMs running in VMWare Fusion Pro 12.2.1 on a 2018 MacBook Pro (x86_64) under macOS 11.6.2. I don't have a "real" Windows or Linux machine.

My current plan is to release v0.33.1 soon that will revert the inclusion of libusb-package (and thus requires users to manually install libusb on non-Linux systems), then continue to try to reproduce and debug. The main focus will be on Windows, since that's the system where installing libusb is the most confusing for users. (For Linux, the use of the libusb-package version of libusb was primarily to ensure consistency.)

I may be able to put together a test script, and will report back to this issue to request help running it on affected systems.

Hello again, I think you can close this issue.

  1. I checked with a J-32 debug probe (Microchip/SEGGER) and the bug did not manifest.
  2. I updated the firmware of my ST-LINK/V2-1 to V2J39M27 and now everything works fine. Maybe you could put this tip on the udev readme and in the debug msg... something like try to update your probe's firmware
vacagonzalo commented 2 years ago

Instantly have this exception when trying to use v0.33.0. For e.g. if i try pyocd list command. My proggramer is ST-link. OS Windows 10. (As i understand i don't need libusb-1.0.dll in Python folder, but i've tried to add it anyway. Doesn't work.)

Everything is good with v0.32.3 and libusb-1.0.dll installed in Python 3.10.1 folder.

0007003 C USB Error: [Errno 10060] Operation timed out [__main__]

Please ask, if you need more information.

Hello @BlokhinDima, I had a similar bug. I updated the probe's firmware and now everything works fine. Maybe you could try that. Best regards.

flit commented 2 years ago

@vacagonzalo That's great! I'll definitely add this to the documentation and udev readme.

Assuming that @BlokhinDima's case is fixed with an STLink firmware upgrade, it's still curious that pyocd 0.32.3 works without the firmware upgrade.

vacagonzalo commented 2 years ago

@flit Sorry, I have bad news... After the firmware update, if I unplug the probe and reconnect it again the bug return. I run the firmware update again and the device can be read by pyocd once again... I checkout to V0.32.3 and everything works fine, even when I disconnect the probe. I will make a test in another PC by Feb 2nd. Sorry.

cederom commented 2 years ago

Some most common issues:

If problem persist you may:

If problem persist you may:

  1. uninstall pip provided pyocd package.
  2. git clone pyocd upstream.
  3. try running release, previous release--, devel branch.
  4. see how you can find a solution for a problem or when+why things start working.
flit commented 2 years ago

@vacagonzalo Thanks for reporting back! That's really strange how the firmware update temporarily fixes it. Good to know pyocd v0.32.3 solves it, the same as for @BlokhinDima.

There seems to be some difference between the libusb included with libusb-package and user-supplied libusb. Though I can't think of what it might be, especially on Linux. (And why it's not reproduceable on my systems.)

libusb 1.0.25 was just released yesterday, so I will update libusb-package and we can see if that fixes anything.

@cederom Thanks for the suggestions.

cederom commented 2 years ago

There seems to be some difference between the libusb included with libusb-package and user-supplied libusb. Though I can't think of what it might be, especially on Linux. (And why it's not reproduceable on my systems.)

libusb 1.0.25 was just released yesterday, so I will update libusb-package and we can see if that fixes anything.

It may be also good to verify the exact underlying LibUSB package information version/variant provided by the OS because Python's library is using it to talk to hardware.. maybe different Linux distro (or even different update of the same distro version) use different LibUSB versions/variant.. that would not be the first time :-)

flit commented 2 years ago

@cederom Indeed! The interesting thing, though, is that @BlokhinDima reported it failing on Windows, too. Presumably he had the latest libusb installed, pre-built by the libusb team—but this needs to be verified. I'm not doing anything special building the libusb in libusb-package for either Windows or Linux, just following the readmes from the libusb repo.

cederom commented 2 years ago

Maybe something changed in the underlying LibUSB provided by the OS?

flit commented 2 years ago

libusb-package was just updated to v1.0.25.0, containing libusb 1.0.25 (naturally).

@vacagonzalo @BlokhinDima If you have a chance, can you try upgrading libusb-package and retested? There were many fixes and changes in this release of libusb. Just run pip install -U libusb-package.

baszn commented 2 years ago

Same problem here, fresh install of pyocd with libusb v1.0.25, STLink firmware version V2J39M7, STM32 STLink driver 2.2.0.0 (1-4-2021) under Windows. Same problem on another Windows 10 PC and another Ubuntu 20.04 laptop.

baszn commented 2 years ago

After running the pyocd list command (and getting the error) the STM32CubeProgrammer is unable to connect to the debugger anymore. After disconnecting and reconnecting the debugger, the device shows up again. It seems like the error in pyocd causes the connection to be lost or to be forever busy/waiting.

BlokhinDima commented 2 years ago

@flit I'm sorry, I'm currently at home due to COVID, I can only check everything when I return to work =( On my work PC, where i first noticed the error i used libusb 1.0.24 and 64-bit python, and i also updated STLink firmware with ST-Link utility but i don't remember firmware version.

BlokhinDima commented 2 years ago

@flit Luckily, I managed to find a programmer at home.

  1. I installed 64-bit version of python3.10.2 and pyocd v0.33.0. OS Windows 11.
  2. I opened ST-Link utility and updated programmer firmware to V2.J34.S7.
  3. Launched pip install -U libusb-package and saw (v1.0.25.0)
  4. I didn't add libusb-1.0.dll to Python folder.

First launch of pyocd list -vv -L "*trace=debug" seems good:

0000544 D setting log level debug for ['pyocd.trace', 'pyocd.coresight.ap.trace', 'pyocd.utility.notification.trace', 'pyocd.coresight.dap.trace', 'pyocd.flash.flash.trace', 'pyocd.debug.semihost.trace', 'pyocd.gdbserver.packet_io.trace', 'pyocd.probe.pydapaccess.interface.hidapi_backend.trace', 'pyocd.probe.pydapaccess.interface.pyusb_backend.trace', 'pyocd.probe.pydapaccess.interface.pyusb_v2_backend.trace', 'pyocd.probe.pydapaccess.interface.pywinusb_backend.trace', 'pyocd.probe.pydapaccess.dap_access_cmsis_dap.trace', 'pyocd.probe.cmsis_dap_probe.trace', 'pyocd.probe.jlink_probe.trace', 'pyocd.probe.tcp_client_probe.trace', 'pyocd.probe.stlink.usb.trace', 'pyocd_pemicro.pemicro_probe.trace', 'pyocd.gdbserver.gdbserver.trace', 'pyocd.probe.tcp_probe_server.trace'] [__main__]
0000544 D Project directory: C:\Users\blokh [session]
0000643 D   USB CMD> (16) f5 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000643 D   USB IN < (req 2 bytes) [usb]
0000643 D   USB IN < (2) 01 00 [usb]
0000643 D   USB CMD> (16) f1 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000643 D   USB IN < (req 6 bytes) [usb]
0000643 D   USB IN < (6) 28 87 83 04 48 37 [usb]
0000643 D STLink probe 540018000700004B474D4D4E firmware version: V2J34M7 [stlink]
0000643 D   USB CMD> (16) f7 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000643 D   USB IN < (req 8 bytes) [usb]
0000643 D   USB IN < (8) ed 05 00 00 fb 07 00 00 [usb]
0000643 D   USB CMD> (16) f5 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000643 D   USB IN < (req 2 bytes) [usb]
0000643 D   USB IN < (2) 01 00 [usb]
0000643 D Fetching mounted devices from disk service registry entry [windows]
0000643 D Fetching usb storage devices from USBSTOR service registry entry [windows]
0000643 D No USBSTOR service found, no device can be detected [windows]
0000643 D target_id_usb_id -> mount_point mapping: {}  [windows]
  #   Probe          Unique ID
-----------------------------------------------
  0   STM32 STLink   540018000700004B474D4D4E

Then after ST-Link programmer was unplugged and plugged again output was the same (for several times)! No errors.

BlokhinDima commented 2 years ago

@flit Did the same on my laptop. Python3.9.5 64-bit. OS Windows 10. No errors. I will try to do the same on my work PC when i will be able to come to the office.

BlokhinDima commented 2 years ago

@flit I've installed firmware version V2.J37.S7 on my ST-Link and problem is here again on my PC and Laptop =( Backup to V2.J34.S7 solves problem. There is one thing i can't understand. ST link utility on my PC detects V2.J34.S7 as recommended. But ST link utility on my laptop detects V2.J37.S7 as recommended version.

BlokhinDima commented 2 years ago

@flit Finally i've updated my programmer using STM32CubeProgrammer to version V2J39S7.

Launch of pyocd list -vv -L "*trace=debug":

0000546 D setting log level debug for ['pyocd.trace', 'pyocd.coresight.ap.trace', 'pyocd.utility.notification.trace', 'pyocd.coresight.dap.trace', 'pyocd.flash.flash.trace', 'pyocd.debug.semihost.trace', 'pyocd.gdbserver.packet_io.trace', 'pyocd.probe.pydapaccess.interface.hidapi_backend.trace', 'pyocd.probe.pydapaccess.interface.pyusb_backend.trace', 'pyocd.probe.pydapaccess.interface.pyusb_v2_backend.trace', 'pyocd.probe.pydapaccess.interface.pywinusb_backend.trace', 'pyocd.probe.pydapaccess.dap_access_cmsis_dap.trace', 'pyocd.probe.cmsis_dap_probe.trace', 'pyocd.probe.jlink_probe.trace', 'pyocd.probe.tcp_client_probe.trace', 'pyocd.probe.stlink.usb.trace', 'pyocd_pemicro.pemicro_probe.trace', 'pyocd.gdbserver.gdbserver.trace', 'pyocd.probe.tcp_probe_server.trace'] [__main__]
0000546 D Project directory: C:\Users\blokh\Desktop\APSTEC_GIT\HardwareQA\magtool [session]
0000657 D   USB CMD> (16) f5 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000658 D   USB IN < (req 2 bytes) [usb]
0000658 D   USB IN < (2) 00 01 [usb]
0000659 D   USB CMD> (16) f3 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000659 D   USB CMD> (16) f1 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000662 D   USB IN < (req 6 bytes) [usb]
0000713 D   USB IN < (6) 29 c7 83 04 48 37 [usb]
0000713 D STLink probe 540018000700004B474D4D4E firmware version: V2J39M7 [stlink]
0000713 D   USB CMD> (16) f7 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000714 D   USB IN < (req 8 bytes) [usb]
0000714 D   USB IN < (8) ed 05 00 00 fb 07 00 00 [usb]
0000715 D   USB CMD> (16) f2 56 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000715 D   USB IN < (req 36 bytes) [usb]
0000716 D   USB IN < (36) 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0000716 D   USB CMD> (16) f5 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [usb]
0001721 C USB Error: [Errno 10060] Operation timed out [__main__]

Backup to ST-Link version V2.J34.S7 solves problem with pyocd v0.33.0

When using ST-Link version V2J39S7. Backup to pyocd v.0.32.3 and libusb 1.0.25 dll file in Python folder solves problem.

baszn commented 2 years ago

Trying the solution of @BlokhinDima under Windows 10 seems te be working fine for me as well (downgraded using pip install pyocd==0.32.3). Not placing the libusb-1.0.dll file in the python root folder results in a No available debug probes are connected error. But when the libusb dll file is placed in the root folder pyocd list works as intended.

flit commented 2 years ago

@BlokhinDima I hope you are feeling better after having Covid!

Thanks for the debug trace—that looks exactly like the trace provided by @vacagonzalo. Basically the 5th command (0xf5, or GET_CURRENT_MODE) hangs and doesn't get a reply from the STLink. Whether the command actually is sent on the USB is not clear.

That's very curious that V2J34 seems to fix it!

I'm going to release v0.33.1 this weekend that reverts the change to use libusb-package. This means a manual installation of libusb will be required, as with v0.32.3 and earlier. Hopefully this issue can be resolved soon. Until I can reproduce it locally to debug what's actually happening inside libusb, that may not be possible unless someone else can debug it. (And I'd love to see a USB bus trace from the failure!) I plan also to create a standalone test script that sends the STLink commands that show the issue, so it's easier to test and reproduce.

flit commented 2 years ago

Finally I can reproduce it, on both Windows and Linux. It took upgrading the firmware to V2J39M27 (from V2J37M27 on this particular Nucleo-G031).

STLinkV3 does not seem to be affected. At least, I've not heard of any reports, nor can I reproduce it after upgrading a Nucleo-H743 to the latest V3 firmware V3J9M3. (Of course, that's not completely certain.)

flit commented 2 years ago

cc @schstm

From my initial investigation, it looks like this is actually a bug in the STLinkV2 firmware. (To my great surprise! As well as relief that it's apparently not something strange with how libusb is built.)

The reason it is connected with pyocd 0.33 is that this version of pyocd adds support for the JTAG_GET_BOARD_IDENTIFIERS command added to STLink V2J36 and V3J6. It's this specific command that causes the timeout error. If the sending of this command is disabled, pyocd connects and communicates with the STLInk just fine.

The attached test_stlink_board_id_timeout.py script is a stripped down version of the code to send the STLink command sequence that reproduces the timeout. It sends the commands to the first available STLink it sees.

Next steps:

test_stlink_board_id_timeout.zip

schstm commented 2 years ago

Hello, The JTAG_GET_BOARD_IDENTIFIERS command always returns 128 bytes on the USB, even if only 36 bytes are useful today. According to the USB trace of the failing case, only 36 bytes are asked by the host on the IN endpoint, which results afterwards in the USB communication loss (ST-Link not ready to process a new command until the previous one finishes). The host must request for 128 bytes after this command. I'm sorry if there was a misunderstanding in the API, but most probably this is the root cause of the issue.

flit commented 2 years ago

@schstm Thanks so much for the hint! (And for the fast reply.) You were, of course, correct—changing the read size to 128 resolves the issue.

My apologies for thinking it might be an STLink bug. There must be a difference in some versions of the STLink firmware, though, because it worked well in my original testing on both V2 and V3, and I was never able to reproduce on V3. Anyway, we have a fix now. 😄

schstm commented 2 years ago

Hello, I investigated a little bit more because I was surprised by your answer [the API at FW level never changed], but you are also right: it can work, especially on the V3, because endpoint size is 512 bytes wide; so the USB IN data is retrieved by the host USB driver in a single request, and the ST-Link is happy ! [I was wrong in my first analysis] Then, the behavior during next command depends on the host implementation: if IN data are flushed before sending a new command, host and device will be aligned again for this new command. On V2 it could be different (I have not tried) as long as endpoint size is 64 bytes, so the host driver must issue 2 IN requests to make the FW 'happy', and I'm not sure it does it if the application asks only for 36 bytes. I don't know if libusb provides the ability to flush endpoints (I did not find in a quick search), but at least winusb does with WinUsb_FlushPipe(), ... and we use it in our STLinkUSBDriver.dll (this increases a little bit the USB comm robustness)