Cortex M3 debugging: Intermittent partial load of binary with pyOCD, then timeout

Question

I'm debugging an embedded system and get intermittent binary loading errors when flashing the binary through gdb (well, arm-none-eabi-gdb, the toolchain gdb client). Here are the details of my setup:

• LPC1768 dev board at firmware rev 141212 (Cortex-M3 processor with CMSIS-DAP debugger interface)
• GCC-ARM Toolchain (including arm-none-eabi-gdb client debugger)
• Target hardware connected via USB serial (nothing special done to connect it, Ubuntu 14.04 just auto-mounted it as a USB storage device)
• pyOCD 0.4.5
• pyusb 1.0.0rcl
• Ubuntu 14.04 as a VirtualBox 5.0.0 guest OS (Win7 host OS).

The GDB server launches on the target (remote) hardware well enough:

${ubuntu:honkaboy} python gdb_test.py
INFO:root:new board id detected: 10100936d079f041404682e3fb480a743a63
INFO:root:board allows 10 concurrent packets
INFO:root:DAP SWD MODE initialised
INFO:root:IDCODE: 0x2BA01477
INFO:root:6 hardware breakpoints, 4 literal comparators
INFO:root:CPU core is Cortex-M3
INFO:root:4 hardware watchpoints
INFO:root:GDB server started at port:3333
INFO:root:One client connected!

And the gdb client launches fine too:

{ubuntu:honkaboy}: /usr/local/gcc-arm-none-eabi-4_9-2015q2/bin/arm-none-eabi-gdb Motion-Control.59.elf
GNU gdb (GNU Tools for ARM Embedded Processors) 7.8.0.20150604-cvs
...
[bunch of omitted startup messages (canned and irrelevant)]
...
Reading symbols from Motion-Control.59.elf...done.
(gdb) target remote localhost:3333
Remote debugging using localhost:3333
0x00003cb0 in Reset_Handler ()

But when I load the binary through the client, I often will get a data transfer timeout:

Client terminal:

(gdb) load
Loading section .text, size 0x11940 lma 0x0
Loading section .ARM.exidx, size 0x8 lma 0x11940
Loading section .data, size 0x134 lma 0x11948
Remote connection closed

Server terminal:

INFO:root:One client connected!
[=======             ]  35%Exception in thread Thread-2:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 810, in __bootstrap_inner
    self.run()
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/gdbserver/gdbserver.py", line 318, in run
    resp, detach = self.handleMsg(packet)
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/gdbserver/gdbserver.py", line 390, in handleMsg
    return self.flashOp(msg[2:]), 0
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/gdbserver/gdbserver.py", line 548, in flashOp
    self.flashBuilder.program(chip_erase = self.chip_erase, progress_cb=progress_cb, fast_verify=self.fast_program)
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/flash/flash_builder.py", line 250, in program
    flash_operation = self._page_erase_program(progress_cb)
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/flash/flash_builder.py", line 486, in _page_erase_program
    data = self.flash.target.readBlockMemoryUnaligned8(page.addr, len(page.data))
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/target/cortex_m.py", line 569, in readBlockMemoryUnaligned8
    mem = self.readBlockMemoryAligned32(addr, size/4)
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/target/cortex_m.py", line 667, in readBlockMemoryAligned32
    resp += self.transport.readBlock32(addr, n/4)
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/transport/cmsis_dap.py", line 221, in readBlock32
    resp = self._transferBlock(size, READ | AP_ACC | AP_REG['DRW'])
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/transport/cmsis_dap.py", line 402, in _transferBlock
    return self.protocol.transferBlock(count, request, data)
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/transport/cmsis_dap_core.py", line 256, in transferBlock
    self.interface.write(cmd)
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/interface/pyusb_backend.py", line 155, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python2.7/dist-packages/usb/core.py", line 360, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python2.7/dist-packages/usb/core.py", line 921, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python2.7/dist-packages/usb/backend/libusb1.py", line 834, in intr_write
    timeout)
  File "/usr/local/lib/python2.7/dist-packages/usb/backend/libusb1.py", line 912, in __write
    _check(retval)
  File "/usr/local/lib/python2.7/dist-packages/usb/backend/libusb1.py", line 592, in _check
    raise USBError(_strerror(ret), ret, _libusb_errno[ret])
USBError: [Errno 110] Operation timed out

Exception in thread gdb-packet-thread (most likely raised during interpreter shutdown):
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 810, in __bootstrap_inner
  File "/usr/local/lib/python2.7/dist-packages/pyOCD/gdbserver/gdbserver.py", line 119, in run
<type 'exceptions.AttributeError'>: 'NoneType' object has no attribute 'error'

As I mentioned, the error is intermittent. It happens probably 70% of the time, the other 30% it loads all the way just fine and I'm able to debug the program normally. The load percentage at which the timeout occurred in my example here was 35%, but that's not consistent. Sometimes it times out at 10% loaded, sometimes 69%, etc.

Answer 1

I have a (band-aid) fix for the issue and two guesses for what might be the underlying cause. I'll give my fix first.

(Disclaimer: I'm not very knowledgeable about pyOCD or pyusb and my fix here was purely heuristically derived. This fix may very well screw up some other functionality of pyOCD or pyusb.)

Increase the pyusb serial write timeout. I'm not sure what the default timeout is, but I got roughly the same failure frequency when I set the write timeout to 1000ms. 2000ms seemed long enough to consistently succeed.

Here's where to change the timeout. Note that I installed pyusb and pyOCD with pip in the default locations on Ubuntu 14.04, which put the file at /usr/local/lib/python2.7/dist-packages/usb/core.py.

Function self.device.write(), at core.py:349 (part of pyusb 1.0.0rcl).

Before (full function for context):

def write(self, data, timeout = None):
    r"""Write data to the endpoint.

    The parameter data contains the data to be sent to the endpoint and
    timeout is the time limit of the operation. The transfer type and
    endpoint address are automatically inferred.

    The method returns the number of bytes written.

    For details, see the Device.write() method.
    """
    return self.device.write(self, data, timeout)

After (only change is default timeout value):

def write(self, data, timeout = 2000):
    r"""Write data to the endpoint.
    [ ... ]
    """
    return self.device.write(self, data, timeout)

Now for my guesses about the underlying issue.

1. I'm running Ubuntu 14.04 as a guest VM via VirtualBox 5.0.0, so it may be that there's some extra latency to the USB endpoint since the USB device has to be mounted through the VM framework.
2. Some bug with pyusb, pyOCD, or the target firmware.

I suspect #1 more than #2. Testing a similar setup natively on Windows (pyocd_win), I don't have any loading timeout issues.