search

Linaro / lite-lava-docker-compose

LITE Team LAVA docker dispatcher
MIT License
5 stars 10 forks source link

frdm_kw41z/frdm_k64f, pyocd & raspi: issue log #145

Open pfalcon opened 3 years ago

pfalcon commented 3 years ago

This ticket is to log progress of investigating issues with flashing frdm_kw41z using pyocd from raspi LAVA worker.

Initial reports from upstream issue https://projects.linaro.org/browse/LSS-1311:

pfalcon commented 3 years ago

cc @galak

pfalcon commented 3 years ago

Yesterday I ran pyocd-based test job on raspi, using: /usr/local/bin/pyocd-flashtool 0.29.0 (the same setup as in Docker, except that we actually install from master branch, so have moving target, not exactly easily reproducing across time).

This very first job failed on 1st flash attempt. Seeing that, I immediately went to the console and re-ran the same pyocd-flashtool command, which succeeded. Getting back to the job, I saw that it was indeed just the 1st flashing attempt. I had failure_retry: 3, and 2nd retry worked, so the whole job was actually successful.

I then updated job to set failure_retry: 1 (so any flashing failure would fail the job), and submitted it 100 times in row. None of them failed. But looking thru the logs closer, I saw:

output: INFO:pyocd.flash.loader:Erased 0 bytes (0 sectors), programmed 0 bytes (0 pages), skipped 32768 bytes (16 pages) at 16.47 kB/s

In other words, no flashing actually occurred, as the flash already contained needed data. These results aren't completely useless either, as some USB communication did take place - 100 times without error. Unclear how much however, e.g. if pyocd read out the flash contents, or comparison magic happened on CMSIS DAP firmware side. All in all, representative test should use 2 interleaving jobs with different test binaries.

For reference, the log for initial flashing failure mentioned above (based on the log, the failure actually happened after flashing per se, during device disconnect):

pyocd-flashtool -d debug -t kw41z4 -f 3000000 --board 0201000036934e45001a40159f3500410e61000097969900 /var/lib/lava/dispatcher/tmp/60/deployimages-f_cm1tfs/zephyr/zephyr.bin
action: flash-pyocd
command: ['pyocd-flashtool', '-d', 'debug', '-t', 'kw41z4', '-f', '3000000', '--board', '0201000036934e45001a40159f3500410e61000097969900', '/var/lib/lava/dispatcher/tmp/60/deployimages-f_cm1tfs/zephyr/zephyr.bin']
message: Command '['pyocd-flashtool', '-d', 'debug', '-t', 'kw41z4', '-f', '3000000', '--board', '0201000036934e45001a40159f3500410e61000097969900', '/var/lib/lava/dispatcher/tmp/60/deployimages-f_cm1tfs/zephyr/zephyr.bin']' returned non-zero exit status 1.
output: WARNING:pyocd.tools.flash_tool:pyocd-flashtool is deprecated; please use the new combined pyocd tool.
DEBUG:pyocd.core.session:Project directory: /
INFO:pyocd.board.board:Target type is kw41z4
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:Detaching Kernel Driver of Interface 3 from USB device (VID=0d28 PID=0204).
DEBUG:pyocd.probe.pydapaccess.dap_access_cmsis_dap:CMSIS-DAP probe 0201000036934e45001a40159f3500410e61000097969900 firmware version: 1.0
DEBUG:pyocd.utility.sequencer:Running task load_svd
DEBUG:pyocd.utility.sequencer:Running task pre_connect
DEBUG:pyocd.utility.sequencer:Running task dp_init
DEBUG:pyocd.utility.sequencer:Running task lock_probe
DEBUG:pyocd.utility.sequencer:Running task get_probe_capabilities
DEBUG:pyocd.utility.sequencer:Running task connect
DEBUG:pyocd.coresight.dap:Default wire protocol selected; using SWD
DEBUG:pyocd.probe.swj:Sending deprecated SWJ sequence to select SWD
INFO:pyocd.coresight.dap:DP IDR = 0x0bc11477 (v1 MINDP rev0)
DEBUG:pyocd.utility.sequencer:Running task clear_sticky_err
DEBUG:pyocd.utility.sequencer:Running task power_up_debug
DEBUG:pyocd.utility.sequencer:Running task check_version
DEBUG:pyocd.utility.sequencer:Running task unlock_probe
DEBUG:pyocd.utility.sequencer:Running task create_discoverer
DEBUG:pyocd.utility.sequencer:Running task discovery
DEBUG:pyocd.utility.sequencer:Running task find_aps
DEBUG:pyocd.utility.sequencer:Running task create_aps
DEBUG:pyocd.utility.sequencer:Running task create_ap.0
INFO:pyocd.coresight.ap:AHB-AP#0 IDR = 0x04770031 (AHB-AP var3 rev0)
DEBUG:pyocd.coresight.ap:AHB-AP#0 default HPROT=3 HNONSEC=0
DEBUG:pyocd.coresight.ap:AHB-AP#0 implemented HPROT=3 HNONSEC=0
DEBUG:pyocd.utility.sequencer:Running task create_ap.1
INFO:pyocd.coresight.ap:AP#1 IDR = 0x001c0020 (AP var2 rev0)
DEBUG:pyocd.utility.sequencer:Running task check_mdm_ap_idr
DEBUG:pyocd.target.family.target_kinetis:MDM-AP version 2
DEBUG:pyocd.utility.sequencer:Running task check_flash_security
INFO:pyocd.target.family.target_kinetis:KW41Z4 not in secure state
DEBUG:pyocd.utility.sequencer:Running task find_components
DEBUG:pyocd.utility.sequencer:Running task init_ap.0
INFO:pyocd.coresight.rom_table:AHB-AP#0 Class 0x1 ROM table #0 @ 0xf0002000 (designer=00e part=000)
INFO:pyocd.coresight.rom_table:[0]<f0000000:MTB-M0+ class=9 designer=43b part=932 devtype=31 archid=0a31 devid=0:0:0>
INFO:pyocd.coresight.rom_table:[1]<f0001000:MTBDWT class=9 designer=00e part=000 devtype=04 archid=0000 devid=0:0:0>
INFO:pyocd.coresight.rom_table:[2]<e00ff000:ROM class=1 designer=43b part=4c0>
INFO:pyocd.coresight.rom_table:  AHB-AP#0 Class 0x1 ROM table #1 @ 0xe00ff000 (designer=43b part=4c0)
INFO:pyocd.coresight.rom_table:  [0]<e000e000:SCS-M0+ class=14 designer=43b part=008>
INFO:pyocd.coresight.rom_table:  [1]<e0001000:DWT-M0+ class=14 designer=43b part=00a>
INFO:pyocd.coresight.rom_table:  [2]<e0002000:BPU class=14 designer=43b part=00b>
DEBUG:pyocd.utility.sequencer:Running task create_cores
DEBUG:pyocd.coresight.discovery:Creating SCS-M0+ component
INFO:pyocd.coresight.cortex_m:CPU core #0 is Cortex-M0+ r0p1
DEBUG:pyocd.utility.sequencer:Running task create_components
DEBUG:pyocd.coresight.discovery:Creating DWT-M0+ component
INFO:pyocd.coresight.dwt:2 hardware watchpoints
DEBUG:pyocd.coresight.discovery:Creating BPU component
INFO:pyocd.coresight.fpb:2 hardware breakpoints, 0 literal comparators
DEBUG:pyocd.coresight.fpb:fpb has been disabled
DEBUG:pyocd.utility.sequencer:Running task check_for_cores
DEBUG:pyocd.utility.sequencer:Running task halt_on_connect
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.utility.sequencer:Running task post_connect
DEBUG:pyocd.utility.sequencer:Running task post_connect_hook
DEBUG:pyocd.utility.sequencer:Running task create_flash
DEBUG:pyocd.utility.sequencer:Running task notify
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:set reset catch, core 0
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:reset, core 0, type=SW_SYSRESETREQ
DEBUG:pyocd.coresight.cortex_m:clear reset catch, core 0
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.flash.builder:Analyze time: 0.146548
DEBUG:pyocd.flash.builder:Chip erase count 16, sector erase est count 16
DEBUG:pyocd.flash.builder:Chip erase weight 3.073200, sector erase weight 3.667200
DEBUG:pyocd.flash.builder:0 of 16 pages have erased data
[---|---|---|---|---|---|---|---|---|----]
[DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
==DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
==DEBUG:pyocd.core.session:uninit session <pyocd.core.session.Session object at 0xffffafc434a8>
DEBUG:pyocd.board.board:uninit board <pyocd.board.mbed_board.MbedBoard object at 0xffffb13d3e10>
ERROR:pyocd.board.board:link exception during target disconnect:
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 466, in program
    flash_operation = self._chip_erase_program(progress_cb)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 681, in _chip_erase_program
    self.flash.program_page(page.addr, page.data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 367, in program_page
    self.target.write_memory_block8(self.begin_data, bytes)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 161, in write_memory_block8
    return self.selected_core.write_memory_block8(addr, value)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 455, in write_memory_block8
    self.ap.write_memory_block8(addr, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/memory_interface.py", line 137, in write_memory_block8
    self.write_memory_block32(addr, data32)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 1063, in _write_memory_block32
    self._write_block32_page(addr, data[:n//4])
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 1013, in _write_block32_page
    self.dp.write_ap_multiple(self.address.address + self._reg_offset + MEM_AP_DRW, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 741, in write_ap_multiple
    return self.probe.write_ap_multiple(addr, values)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 327, in write_ap_multiple
    return self._link.reg_write_repeat(len(values), ap_reg, values, dap_index=0)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 869, in reg_write_repeat
    self._write(dap_index, num_repeats, request, data_array)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 1032, in _write
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/board/board.py", line 98, in uninit
    self.target.disconnect(resume)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 131, in disconnect
    core.disconnect(resume)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 323, in disconnect
    self.resume()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 869, in resume
    if self.get_state() != Target.State.HALTED:
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 830, in get_state
    dhcsr = self.read_memory(CortexM.DHCSR)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 435, in read_memory
    result = self.ap.read_memory(addr, transfer_size, now)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 993, in _read_memory
    result = read_mem_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 972, in read_mem_cb
    res = result_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 717, in read_ap_cb
    result = result_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 286, in read_ap_result_callback
    return result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 847, in read_reg_cb
    res = transfer.get_result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 144, in get_result
    self.daplink.flush()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 669, in flush
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out
ERROR:pyocd.core.session:probe exception during disconnect:
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 466, in program
    flash_operation = self._chip_erase_program(progress_cb)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 681, in _chip_erase_program
    self.flash.program_page(page.addr, page.data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 367, in program_page
    self.target.write_memory_block8(self.begin_data, bytes)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 161, in write_memory_block8
    return self.selected_core.write_memory_block8(addr, value)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 455, in write_memory_block8
    self.ap.write_memory_block8(addr, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/memory_interface.py", line 137, in write_memory_block8
    self.write_memory_block32(addr, data32)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 1063, in _write_memory_block32
    self._write_block32_page(addr, data[:n//4])
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 1013, in _write_block32_page
    self.dp.write_ap_multiple(self.address.address + self._reg_offset + MEM_AP_DRW, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 741, in write_ap_multiple
    return self.probe.write_ap_multiple(addr, values)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 327, in write_ap_multiple
    return self._link.reg_write_repeat(len(values), ap_reg, values, dap_index=0)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 869, in reg_write_repeat
    self._write(dap_index, num_repeats, request, data_array)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 1032, in _write
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 204, in disconnect
    self._link.disconnect()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 729, in disconnect
    self._protocol.disconnect()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/cmsis_dap_core.py", line 198, in disconnect
    raise DAPAccessIntf.DeviceError("expected DAP_DISCONNECT")
pyocd.probe.pydapaccess.dap_access_api.DAPAccessIntf.DeviceError: expected DAP_DISCONNECT

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/session.py", line 483, in close
    self._probe.disconnect()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 207, in disconnect
    six.raise_from(self._convert_exception(exc), exc)
  File "<string>", line 3, in raise_from
pyocd.core.exceptions.ProbeError: expected DAP_DISCONNECT
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:closing interface
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.7/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 144, in rx_task
    self.rcv_data.append(self.ep_in.read(self.ep_in.wMaxPacketSize, 10 * 1000))
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 421, in read
    return self.device.read(self, size_or_buffer, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 1022, in read
    self.__get_timeout(timeout))
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 869, in intr_read
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 954, in __read
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out

Traceback (most recent call last):
  File "/usr/local/bin/pyocd-flashtool", line 10, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 466, in program
    flash_operation = self._chip_erase_program(progress_cb)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 681, in _chip_erase_program
    self.flash.program_page(page.addr, page.data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 367, in program_page
    self.target.write_memory_block8(self.begin_data, bytes)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 161, in write_memory_block8
    return self.selected_core.write_memory_block8(addr, value)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 455, in write_memory_block8
    self.ap.write_memory_block8(addr, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/memory_interface.py", line 137, in write_memory_block8
    self.write_memory_block32(addr, data32)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 1063, in _write_memory_block32
    self._write_block32_page(addr, data[:n//4])
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 1013, in _write_block32_page
    self.dp.write_ap_multiple(self.address.address + self._reg_offset + MEM_AP_DRW, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 741, in write_ap_multiple
    return self.probe.write_ap_multiple(addr, values)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 327, in write_ap_multiple
    return self._link.reg_write_repeat(len(values), ap_reg, values, dap_index=0)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 869, in reg_write_repeat
    self._write(dap_index, num_repeats, request, data_array)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 1032, in _write
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out
['pyocd-flashtool', '-d', 'debug', '-t', 'kw41z4', '-f', '3000000', '--board', '0201000036934e45001a40159f3500410e61000097969900', '/var/lib/lava/dispatcher/tmp/60/deployimages-f_cm1tfs/zephyr/zephyr.bin'] command failed
end: 2.1.1 flash-pyocd (duration 00:00:16) [common]
pfalcon commented 3 years ago

Ok, I now ran properly interleaved 100 jobs. Of them, just one failed, log below. Fore reference (programmed binary sizes were:

output: INFO:pyocd.flash.loader:Erased chip, programmed 32768 bytes (16 pages), skipped 0 bytes (0 pages) at 8.38 kB/s
output: INFO:pyocd.flash.loader:Erased chip, programmed 38912 bytes (19 pages), skipped 0 bytes (0 pages) at 8.70 kB/s

Granted, ~32K isn't really much, but in the Lab, failures quoted above happened with the binary of 12168 bytes.

pyocd-flashtool -d debug -t kw41z4 -f 3000000 --board 0201000036934e45001a40159f3500410e61000097969900 /var/lib/lava/dispatcher/tmp/210/deployimages-48wz3eig/zephyr/zephyr.bin
action: flash-pyocd
command: ['pyocd-flashtool', '-d', 'debug', '-t', 'kw41z4', '-f', '3000000', '--board', '0201000036934e45001a40159f3500410e61000097969900', '/var/lib/lava/dispatcher/tmp/210/deployimages-48wz3eig/zephyr/zephyr.bin']
message: Command '['pyocd-flashtool', '-d', 'debug', '-t', 'kw41z4', '-f', '3000000', '--board', '0201000036934e45001a40159f3500410e61000097969900', '/var/lib/lava/dispatcher/tmp/210/deployimages-48wz3eig/zephyr/zephyr.bin']' returned non-zero exit status 1.
output: WARNING:pyocd.tools.flash_tool:pyocd-flashtool is deprecated; please use the new combined pyocd tool.
DEBUG:pyocd.core.session:Project directory: /
INFO:pyocd.board.board:Target type is kw41z4
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:Detaching Kernel Driver of Interface 3 from USB device (VID=0d28 PID=0204).
DEBUG:pyocd.probe.pydapaccess.dap_access_cmsis_dap:CMSIS-DAP probe 0201000036934e45001a40159f3500410e61000097969900 firmware version: 1.0
DEBUG:pyocd.utility.sequencer:Running task load_svd
DEBUG:pyocd.utility.sequencer:Running task pre_connect
DEBUG:pyocd.utility.sequencer:Running task dp_init
DEBUG:pyocd.utility.sequencer:Running task lock_probe
DEBUG:pyocd.utility.sequencer:Running task get_probe_capabilities
DEBUG:pyocd.utility.sequencer:Running task connect
DEBUG:pyocd.coresight.dap:Default wire protocol selected; using SWD
DEBUG:pyocd.probe.swj:Sending deprecated SWJ sequence to select SWD
INFO:pyocd.coresight.dap:DP IDR = 0x0bc11477 (v1 MINDP rev0)
DEBUG:pyocd.utility.sequencer:Running task clear_sticky_err
DEBUG:pyocd.utility.sequencer:Running task power_up_debug
DEBUG:pyocd.utility.sequencer:Running task check_version
DEBUG:pyocd.utility.sequencer:Running task unlock_probe
DEBUG:pyocd.utility.sequencer:Running task create_discoverer
DEBUG:pyocd.utility.sequencer:Running task discovery
DEBUG:pyocd.utility.sequencer:Running task find_aps
DEBUG:pyocd.utility.sequencer:Running task create_aps
DEBUG:pyocd.utility.sequencer:Running task create_ap.0
INFO:pyocd.coresight.ap:AHB-AP#0 IDR = 0x04770031 (AHB-AP var3 rev0)
DEBUG:pyocd.coresight.ap:AHB-AP#0 default HPROT=3 HNONSEC=0
DEBUG:pyocd.coresight.ap:AHB-AP#0 implemented HPROT=3 HNONSEC=0
DEBUG:pyocd.utility.sequencer:Running task create_ap.1
INFO:pyocd.coresight.ap:AP#1 IDR = 0x001c0020 (AP var2 rev0)
DEBUG:pyocd.utility.sequencer:Running task check_mdm_ap_idr
DEBUG:pyocd.target.family.target_kinetis:MDM-AP version 2
DEBUG:pyocd.utility.sequencer:Running task check_flash_security
INFO:pyocd.target.family.target_kinetis:KW41Z4 not in secure state
DEBUG:pyocd.utility.sequencer:Running task find_components
DEBUG:pyocd.utility.sequencer:Running task init_ap.0
INFO:pyocd.coresight.rom_table:AHB-AP#0 Class 0x1 ROM table #0 @ 0xf0002000 (designer=00e part=000)
INFO:pyocd.coresight.rom_table:[0]<f0000000:MTB-M0+ class=9 designer=43b part=932 devtype=31 archid=0a31 devid=0:0:0>
INFO:pyocd.coresight.rom_table:[1]<f0001000:MTBDWT class=9 designer=00e part=000 devtype=04 archid=0000 devid=0:0:0>
INFO:pyocd.coresight.rom_table:[2]<e00ff000:ROM class=1 designer=43b part=4c0>
INFO:pyocd.coresight.rom_table:  AHB-AP#0 Class 0x1 ROM table #1 @ 0xe00ff000 (designer=43b part=4c0)
INFO:pyocd.coresight.rom_table:  [0]<e000e000:SCS-M0+ class=14 designer=43b part=008>
INFO:pyocd.coresight.rom_table:  [1]<e0001000:DWT-M0+ class=14 designer=43b part=00a>
INFO:pyocd.coresight.rom_table:  [2]<e0002000:BPU class=14 designer=43b part=00b>
DEBUG:pyocd.utility.sequencer:Running task create_cores
DEBUG:pyocd.coresight.discovery:Creating SCS-M0+ component
INFO:pyocd.coresight.cortex_m:CPU core #0 is Cortex-M0+ r0p1
DEBUG:pyocd.utility.sequencer:Running task create_components
DEBUG:pyocd.coresight.discovery:Creating DWT-M0+ component
INFO:pyocd.coresight.dwt:2 hardware watchpoints
DEBUG:pyocd.coresight.discovery:Creating BPU component
INFO:pyocd.coresight.fpb:2 hardware breakpoints, 0 literal comparators
DEBUG:pyocd.coresight.fpb:fpb has been disabled
DEBUG:pyocd.utility.sequencer:Running task check_for_cores
DEBUG:pyocd.utility.sequencer:Running task halt_on_connect
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.utility.sequencer:Running task post_connect
DEBUG:pyocd.utility.sequencer:Running task post_connect_hook
DEBUG:pyocd.utility.sequencer:Running task create_flash
DEBUG:pyocd.utility.sequencer:Running task notify
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:set reset catch, core 0
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:reset, core 0, type=SW_SYSRESETREQ
DEBUG:pyocd.coresight.cortex_m:clear reset catch, core 0
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.flash.builder:Analyze time: 0.123160
DEBUG:pyocd.flash.builder:Chip erase count 19, sector erase est count 19
DEBUG:pyocd.flash.builder:Chip erase weight 3.616800, sector erase weight 4.354800
DEBUG:pyocd.flash.builder:0 of 19 pages have erased data
[---|---|---|---|---|---|---|---|---|----]
[DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
=DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
==DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
==DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
==DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
==DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
==DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
==DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.core.session:uninit session <pyocd.core.session.Session object at 0xffffbbcef780>
DEBUG:pyocd.board.board:uninit board <pyocd.board.mbed_board.MbedBoard object at 0xffffba2875f8>
ERROR:pyocd.board.board:link exception during target disconnect:
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 466, in program
    flash_operation = self._chip_erase_program(progress_cb)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 681, in _chip_erase_program
    self.flash.program_page(page.addr, page.data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 370, in program_page
    result = self._call_function_and_wait(self.flash_algo['pc_program_page'], address, len(bytes), self.begin_data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 585, in _call_function_and_wait
    return self.wait_for_completion()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 533, in wait_for_completion
    while self.target.get_state() == Target.State.RUNNING:
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 223, in get_state
    return self.selected_core.get_state()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 830, in get_state
    dhcsr = self.read_memory(CortexM.DHCSR)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 435, in read_memory
    result = self.ap.read_memory(addr, transfer_size, now)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 993, in _read_memory
    result = read_mem_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 972, in read_mem_cb
    res = result_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 717, in read_ap_cb
    result = result_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 286, in read_ap_result_callback
    return result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 847, in read_reg_cb
    res = transfer.get_result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 144, in get_result
    self.daplink.flush()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 669, in flush
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/board/board.py", line 98, in uninit
    self.target.disconnect(resume)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 131, in disconnect
    core.disconnect(resume)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 323, in disconnect
    self.resume()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 869, in resume
    if self.get_state() != Target.State.HALTED:
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 830, in get_state
    dhcsr = self.read_memory(CortexM.DHCSR)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 435, in read_memory
    result = self.ap.read_memory(addr, transfer_size, now)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 993, in _read_memory
    result = read_mem_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 972, in read_mem_cb
    res = result_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 717, in read_ap_cb
    result = result_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 286, in read_ap_result_callback
    return result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 847, in read_reg_cb
    res = transfer.get_result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 144, in get_result
    self.daplink.flush()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 669, in flush
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:closing interface
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.7/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 144, in rx_task
    self.rcv_data.append(self.ep_in.read(self.ep_in.wMaxPacketSize, 10 * 1000))
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 421, in read
    return self.device.read(self, size_or_buffer, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 1022, in read
    self.__get_timeout(timeout))
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 869, in intr_read
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 954, in __read
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out

Traceback (most recent call last):
  File "/usr/local/bin/pyocd-flashtool", line 10, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 466, in program
    flash_operation = self._chip_erase_program(progress_cb)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 681, in _chip_erase_program
    self.flash.program_page(page.addr, page.data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 370, in program_page
    result = self._call_function_and_wait(self.flash_algo['pc_program_page'], address, len(bytes), self.begin_data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 585, in _call_function_and_wait
    return self.wait_for_completion()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 533, in wait_for_completion
    while self.target.get_state() == Target.State.RUNNING:
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 223, in get_state
    return self.selected_core.get_state()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 830, in get_state
    dhcsr = self.read_memory(CortexM.DHCSR)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 435, in read_memory
    result = self.ap.read_memory(addr, transfer_size, now)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 993, in _read_memory
    result = read_mem_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 972, in read_mem_cb
    res = result_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 717, in read_ap_cb
    result = result_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 286, in read_ap_result_callback
    return result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 847, in read_reg_cb
    res = transfer.get_result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 144, in get_result
    self.daplink.flush()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 669, in flush
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out
['pyocd-flashtool', '-d', 'debug', '-t', 'kw41z4', '-f', '3000000', '--board', '0201000036934e45001a40159f3500410e61000097969900', '/var/lib/lava/dispatcher/tmp/210/deployimages-48wz3eig/zephyr/zephyr.bin'] command failed
pfalcon commented 3 years ago

I now ran test batch with much larger test binary (~270K), and with it, error rate is much more noticeable. More interesting, is that in comes in waves. What I got was (C - LAVA "Complete", I - LAVA "Incomplete" result):

7C - 1I - 33C - 1I - 3C - 42I - 2C - 1I - 8C

(That makes 98 total, minor errors in counting apparently).

Lone "incompletes" are always for lite-aeolus-micropython, i.e.270K binary. But as can be seen, there was a long stride of 42 failures in row, which of course affected even smaller (~32K) test binary.

pfalcon commented 3 years ago

Looking at a couple of random failed jobs inside that 42-stride, it's like:

DEBUG:pyocd.coresight.cortex_m:reset, core 0, type=SW_SYSRESETREQ
WARNING:pyocd.coresight.cortex_m:Timed out waiting for target to complete reset (state is RESET)
DEBUG:pyocd.coresight.cortex_m:clear reset catch, core 0
DEBUG:pyocd.core.session:uninit session <pyocd.core.session.Session object at 0xffffbc62f438>
DEBUG:pyocd.board.board:uninit board <pyocd.board.mbed_board.MbedBoard object at 0xffffbd0cb860>
DEBUG:pyocd.coresight.cortex_m:cannot resume: target not halted
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:closing interface
Traceback (most recent call last):
  File "/usr/local/bin/pyocd-flashtool", line 10, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 421, in program
    self._build_sectors_and_pages(keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 319, in _build_sectors_and_pages
    fill_end_of_page_gap()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 263, in fill_end_of_page_gap
    self._enable_read_access()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 222, in _enable_read_access
    self.flash.init(self.flash.Operation.VERIFY)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 246, in init
    r0=address, r1=clock, r2=operation.value, init=True)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 584, in _call_function_and_wait
    self._call_function(pc, r0, r1, r2, r3, init)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 524, in _call_function
    self.target.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 188, in write_core_registers_raw
    self.selected_core.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1095, in write_core_registers_raw
    self._base_write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1113, in _base_write_core_registers_raw
    self.core_number))
pyocd.core.exceptions.CoreRegisterAccessError: cannot write registers pc, r0, r1, r2, r9, sp, lr because core #0 is not halted

As can be seen, it's not even USB Error per se (at least, as reported).

pfalcon commented 3 years ago

And it apparently happened even before flashrom writing per se.

(And it's not like failures seen in the Lab still.)

pfalcon commented 3 years ago

Lone failed jobs are definitely USB timeouts.

So, all in all, it's still not clear how much the raspi is guilty in those issues...

pfalcon commented 3 years ago

Ok, I got no better idea than to re-run the 100-batch again. Because that 42-stride is effectively a long, but a single case of failure, and 1 failure is non-conclusive.

With the new batch, I got 9 failures total. Of them, there was a streak of 4, but not like "Timed out waiting for target to complete reset", the rest a spread-out standalone cases.

There was a new interesting error specimen:

pyocd-flashtool -d debug -t kw41z4 -f 3000000 --board 0201000036934e45001a40159f3500410e61000097969900 /var/lib/lava/dispatcher/tmp/378/deployimages-r00cvnqt/zephyr/zephyr.bin
action: flash-pyocd
command: ['pyocd-flashtool', '-d', 'debug', '-t', 'kw41z4', '-f', '3000000', '--board', '0201000036934e45001a40159f3500410e61000097969900', '/var/lib/lava/dispatcher/tmp/378/deployimages-r00cvnqt/zephyr/zephyr.bin']
message: Command '['pyocd-flashtool', '-d', 'debug', '-t', 'kw41z4', '-f', '3000000', '--board', '0201000036934e45001a40159f3500410e61000097969900', '/var/lib/lava/dispatcher/tmp/378/deployimages-r00cvnqt/zephyr/zephyr.bin']' returned non-zero exit status 1.
output: WARNING:pyocd.tools.flash_tool:pyocd-flashtool is deprecated; please use the new combined pyocd tool.
DEBUG:pyocd.core.session:Project directory: /
INFO:pyocd.board.board:Target type is kw41z4
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 148, in open
    self._link.open()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 597, in open
    self._packet_count = self._protocol.dap_info(self.ID.MAX_PACKET_COUNT)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/cmsis_dap_core.py", line 138, in dap_info
    raise DAPAccessIntf.DeviceError("expected DAP_INFO")
pyocd.probe.pydapaccess.dap_access_api.DeviceError: expected DAP_INFO

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/bin/pyocd-flashtool", line 10, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 161, in main
    with session:
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/session.py", line 343, in __enter__
    self.open()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/session.py", line 457, in open
    self._probe.open()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 168, in open
    six.raise_from(self._convert_exception(exc), exc)
  File "<string>", line 3, in raise_from
pyocd.core.exceptions.ProbeError: expected DAP_INFO
['pyocd-flashtool', '-d', 'debug', '-t', 'kw41z4', '-f', '3000000', '--board', '0201000036934e45001a40159f3500410e61000097969900', '/var/lib/lava/dispatcher/tmp/378/deployimages-r00cvnqt/zephyr/zephyr.bin'] command failed
pfalcon commented 3 years ago

My conclusion: medium-scale testing of frdm_kw41z/pyocd/raspi combo didn't show that usage of raspi can be attributed to visibly affecting reliability of pyocd flashing (with the latest version of pyocd).

Reliability on its own is not enough for production usage, but that can be addressed by separate measures: a) using LAVA flashing ("boot" action specifically, as flashing happens in it) failure_retry setting; b) trying recent bootloader firmware (I didn't upgrade mine, and its pretty old).

pfalcon commented 3 years ago

For reference, I now have got USB timeout running pyocd 0.29.0 against frdm_k64f on raspi. So yes, these issue are real. (Except somehow they happen too often in the lab, and less often here locally.)

DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:set reset catch, core 0
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:reset, core 0, type=SW_SYSRESETREQ
DEBUG:pyocd.coresight.cortex_m:clear reset catch, core 0
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.coresight.cortex_m:resuming core 0
DEBUG:pyocd.debug.breakpoints.manager:added=[] removed=[]
DEBUG:pyocd.debug.breakpoints.manager:bps after flush={}
DEBUG:pyocd.flash.builder:Analyze time: 0.238195
DEBUG:pyocd.flash.builder:Chip erase count 6, sector erase est count 0
DEBUG:pyocd.flash.builder:Chip erase weight 1.568400, sector erase weight 0.902400
DEBUG:pyocd.flash.builder:Using double buffer sector erase program
[=============       ]  68%DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.core.session:uninit session <pyocd.core.session.Session object at 0xffff992dc898>
DEBUG:pyocd.board.board:uninit board <pyocd.board.mbed_board.MbedBoard object at 0xffff990ba828>
ERROR:pyocd.board.board:link exception during target disconnect:
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 470, in program
    flash_operation = self._sector_erase_program_double_buffer(progress_cb)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 863, in _sector_erase_program_double_buffer
    self.flash.init(self.flash.Operation.ERASE)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 246, in init
    r0=address, r1=clock, r2=operation.value, init=True)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 584, in _call_function_and_wait
    self._call_function(pc, r0, r1, r2, r3, init)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 524, in _call_function
    self.target.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 188, in write_core_registers_raw
    self.selected_core.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1095, in write_core_registers_raw
    self._base_write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1156, in _base_write_core_registers_raw
    self.write_memory(CortexM.DCRSR, reg | CortexM.DCRSR_REGWnR)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 429, in write_memory
    self.ap.write_memory(addr, value, transfer_size)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 915, in _write_memory
    self.write_reg(self._reg_offset + MEM_AP_TAR, addr)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 873, in write_reg
    self.dp.write_ap(self.address.address + addr, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 687, in write_ap
    self.probe.write_ap(addr, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 298, in write_ap
    self._link.write_reg(ap_reg, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 830, in write_reg
    self._write(dap_index, 1, request, [value])
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 1032, in _write
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/board/board.py", line 98, in uninit
    self.target.disconnect(resume)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 132, in disconnect
    self.dp.power_down_debug()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 461, in power_down_debug
    r = self.read_reg(DP_CTRL_STAT)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 418, in read_reg
    return self.read_dp(addr, now)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 633, in read_dp
    return read_dp_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 621, in read_dp_cb
    result = result_cb()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 257, in read_dp_result_callback
    return result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 847, in read_reg_cb
    res = transfer.get_result()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 144, in get_result
    self.daplink.flush()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 669, in flush
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out
ERROR:pyocd.core.session:probe exception during disconnect:
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 470, in program
    flash_operation = self._sector_erase_program_double_buffer(progress_cb)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 863, in _sector_erase_program_double_buffer
    self.flash.init(self.flash.Operation.ERASE)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 246, in init
    r0=address, r1=clock, r2=operation.value, init=True)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 584, in _call_function_and_wait
    self._call_function(pc, r0, r1, r2, r3, init)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 524, in _call_function
    self.target.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 188, in write_core_registers_raw
    self.selected_core.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1095, in write_core_registers_raw
    self._base_write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1156, in _base_write_core_registers_raw
    self.write_memory(CortexM.DCRSR, reg | CortexM.DCRSR_REGWnR)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 429, in write_memory
    self.ap.write_memory(addr, value, transfer_size)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 915, in _write_memory
    self.write_reg(self._reg_offset + MEM_AP_TAR, addr)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 873, in write_reg
    self.dp.write_ap(self.address.address + addr, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 687, in write_ap
    self.probe.write_ap(addr, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 298, in write_ap
    self._link.write_reg(ap_reg, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 830, in write_reg
    self._write(dap_index, 1, request, [value])
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 1032, in _write
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 204, in disconnect
    self._link.disconnect()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 729, in disconnect
    self._protocol.disconnect()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/cmsis_dap_core.py", line 198, in disconnect
    raise DAPAccessIntf.DeviceError("expected DAP_DISCONNECT")
pyocd.probe.pydapaccess.dap_access_api.DAPAccessIntf.DeviceError: expected DAP_DISCONNECT

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/session.py", line 483, in close
    self._probe.disconnect()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 207, in disconnect
    six.raise_from(self._convert_exception(exc), exc)
  File "<string>", line 3, in raise_from
pyocd.core.exceptions.ProbeError: expected DAP_DISCONNECT
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:closing interface
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.7/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 144, in rx_task
    self.rcv_data.append(self.ep_in.read(self.ep_in.wMaxPacketSize, 10 * 1000))
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 421, in read
    return self.device.read(self, size_or_buffer, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 1022, in read
    self.__get_timeout(timeout))
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 869, in intr_read
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 954, in __read
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out

Traceback (most recent call last):
  File "/usr/local/bin/pyocd-flashtool", line 10, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 470, in program
    flash_operation = self._sector_erase_program_double_buffer(progress_cb)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 863, in _sector_erase_program_double_buffer
    self.flash.init(self.flash.Operation.ERASE)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 246, in init
    r0=address, r1=clock, r2=operation.value, init=True)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 584, in _call_function_and_wait
    self._call_function(pc, r0, r1, r2, r3, init)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 524, in _call_function
    self.target.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 188, in write_core_registers_raw
    self.selected_core.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1095, in write_core_registers_raw
    self._base_write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1156, in _base_write_core_registers_raw
    self.write_memory(CortexM.DCRSR, reg | CortexM.DCRSR_REGWnR)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 429, in write_memory
    self.ap.write_memory(addr, value, transfer_size)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 915, in _write_memory
    self.write_reg(self._reg_offset + MEM_AP_TAR, addr)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/ap.py", line 873, in write_reg
    self.dp.write_ap(self.address.address + addr, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/dap.py", line 687, in write_ap
    self.probe.write_ap(addr, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/cmsis_dap_probe.py", line 298, in write_ap
    self._link.write_reg(ap_reg, data)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 830, in write_reg
    self._write(dap_index, 1, request, [value])
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 1032, in _write
    self._send_packet()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/utility/concurrency.py", line 28, in _locking
    return func(self, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/dap_access_cmsis_dap.py", line 980, in _send_packet
    self._interface.write(list(data))
  File "/usr/local/lib/python3.7/dist-packages/pyocd/probe/pydapaccess/interface/pyusb_backend.py", line 198, in write
    self.ep_out.write(data)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 406, in write
    return self.device.write(self, data, timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/core.py", line 982, in write
    self.__get_timeout(timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 860, in intr_write
    timeout)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 938, in __write
    _check(retval)
  File "/usr/local/lib/python3.7/dist-packages/usb/backend/libusb1.py", line 602, in _check
    raise USBTimeoutError(_strerror(ret), ret, _libusb_errno[ret])
usb.core.USBTimeoutError: [Errno 110] Operation timed out
pfalcon commented 3 years ago

Locally:

DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:closing interface
Traceback (most recent call last):
  File "/usr/local/bin/pyocd-flashtool", line 10, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 421, in program
    self._build_sectors_and_pages(keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 319, in _build_sectors_and_pages
    fill_end_of_page_gap()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 263, in fill_end_of_page_gap
    self._enable_read_access()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 222, in _enable_read_access
    self.flash.init(self.flash.Operation.VERIFY)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 246, in init
    r0=address, r1=clock, r2=operation.value, init=True)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 584, in _call_function_and_wait
    self._call_function(pc, r0, r1, r2, r3, init)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 524, in _call_function
    self.target.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 188, in write_core_registers_raw
    self.selected_core.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1095, in write_core_registers_raw
    self._base_write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1113, in _base_write_core_registers_raw
    self.core_number))
pyocd.core.exceptions.CoreRegisterAccessError: cannot write registers pc, r0, r1, r2, r9, sp, lr because core #0 is not halted
pfalcon commented 3 years ago

Capturing differences between Lab's and my setup.

Lab:

# uname -a
Linux pi-worker01 5.9.0-1-arm64 #1 SMP Debian 5.9.1-1 (2020-10-17) aarch64 GNU/Linux

local:

# uname -a
Linux pi-worker01 5.8.0-0.bpo.2-arm64 #1 SMP Debian 5.8.10-1~bpo10+1 (2020-09-26) aarch64 GNU/Linux

Lab:

# uhubctl 
Current status for hub 2 [1d6b:0003 Linux 5.9.0-1-arm64 xhci-hcd xHCI Host Controller 0000:01:00.0, USB 3.00, 4 ports]
  Port 1: 0203 power 5gbps U0 enable connect [174c:55aa ASMT ASM105x 123456791717]
  Port 2: 02a0 power 5gbps Rx.Detect
  Port 3: 02a0 power 5gbps Rx.Detect
  Port 4: 02a0 power 5gbps Rx.Detect
Current status for hub 1-1 [2109:3431 USB2.0 Hub, USB 2.10, 4 ports]
  Port 1: 0100 power
  Port 2: 0100 power
  Port 3: 0103 power enable connect [0d28:0204 ARM DAPLink CMSIS-DAP 0240000034544e45004d00028aa900222011000097969900]
  Port 4: 0100 power
Current status for hub 1 [1d6b:0002 Linux 5.9.0-1-arm64 xhci-hcd xHCI Host Controller 0000:01:00.0]
  Port 1: 0503 power highspeed enable connect [2109:3431 USB2.0 Hub, USB 2.10, 4 ports]

local:

# ./uhubctl 
Current status for hub 2 [1d6b:0003 Linux 5.8.0-0.bpo.2-arm64 xhci-hcd xHCI Host Controller 0000:01:00.0, USB 3.00, 4 ports, ppps]
  Port 1: 02a0 power 5gbps Rx.Detect
  Port 2: 0203 power 5gbps U0 enable connect [090c:1000 Samsung Flash Drive FIT 0375018100019762]
  Port 3: 02a0 power 5gbps Rx.Detect
  Port 4: 0080 off
Current status for hub 1-1 [2109:3431 USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 1: 0100 power
  Port 2: 0100 power
  Port 3: 0100 power
  Port 4: 0103 power enable connect [0d28:0204 ARM DAPLink CMSIS-DAP 0240000034544e45000500018aa900222011000097969900]
Current status for hub 1 [1d6b:0002 Linux 5.8.0-0.bpo.2-arm64 xhci-hcd xHCI Host Controller 0000:01:00.0, USB 2.00, 1 ports, ppps]
  Port 1: 0503 power highspeed enable connect [2109:3431 USB2.0 Hub, USB 2.10, 4 ports, ppps]
pfalcon commented 3 years ago

Lab:

# LD_LIBRARY_PATH=. ./vcgencmd version
Jan  7 2021 18:27:29 
Copyright (c) 2012 Broadcom
version fb345a0c2d5544957f4ba1a2b9e968970e3312c4 (clean) (release) (start)

local:

# LD_LIBRARY_PATH=. ./vcgencmd version
Jun  1 2020 13:23:40 
Copyright (c) 2012 Broadcom
version 6379679d1ec6a8c746d7e77e015f5b56b939976f (clean) (release) (start)
pfalcon commented 3 years ago

Lab:

# LD_LIBRARY_PATH=. ./vcgencmd bootloader_version 
Jul 15 2019 12:59:55
version 514670a211212cbbbbd5bcf91555c86ca4750897 (release)
timestamp 1563195595
update-time 0
capabilities 0x00000000

local:

# LD_LIBRARY_PATH=. ./vcgencmd bootloader_version 
Dec 11 2020 11:15:17
version c3f26b6070054bca030366de2550d79ddae1207a (release)
timestamp 1607685317

While the Lab happens to have newer other stuff, this is significantly older.

pfalcon commented 3 years ago

Lab:

# lspci -d 1106:3483 -xxx | awk '/^50:/ { print "VL805 FW version: " $5 $4 $3 $2 }'
VL805 FW version: 00013701

local:

# lspci -d 1106:3483 -xxx | awk '/^50:/ { print "VL805 FW version: " $5 $4 $3 $2 }'
VL805 FW version: 000138a1

Now, we can't dismiss such a difference in USB host controller firmware. I'll be requesting firmware upgrade on Lab's raspi.

pfalcon commented 3 years ago

In https://projects.linaro.org/browse/LSS-2111?focusedCommentId=111263&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-111263, Lab's pi-worker01.lavalab's USB firmware was upgraded, and now:

# lspci -d 1106:3483 -xxx | awk '/^50:/ { print "VL805 FW version: " $5 $4 $3 $2 }'
VL805 FW version: 000138a1

i.e. exactly what I have locally. It also clearly helped with USB timeout errors, but we're now back to other pyocd 0.29.0 errors, similar to those which we saw with weary-flash boards on the x86 dispatcher. Investigating...

pfalcon commented 3 years ago 
# pyocd-flashtool -d debug -t k64f -f 3000000 --board 0240000034544e45004d00028aa900222011000097969900 zephyr.bin
WARNING:pyocd.tools.flash_tool:pyocd-flashtool is deprecated; please use the new combined pyocd tool.
DEBUG:pyocd.core.session:Project directory: /root
INFO:pyocd.board.board:Target type is k64f
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:Detaching Kernel Driver of Interface 3 from USB device (VID=0d28 PID=0204).
DEBUG:pyocd.probe.pydapaccess.dap_access_cmsis_dap:CMSIS-DAP probe 0240000034544e45004d00028aa900222011000097969900 firmware version: 1.10
DEBUG:pyocd.utility.sequencer:Running task load_svd
DEBUG:pyocd.utility.sequencer:Running task pre_connect
DEBUG:pyocd.utility.sequencer:Running task dp_init
DEBUG:pyocd.utility.sequencer:Running task lock_probe
DEBUG:pyocd.utility.sequencer:Running task get_probe_capabilities
DEBUG:pyocd.utility.sequencer:Running task connect
DEBUG:pyocd.coresight.dap:Default wire protocol selected; using SWD
DEBUG:pyocd.probe.swj:Sending deprecated SWJ sequence to select SWD
INFO:pyocd.coresight.dap:DP IDR = 0x2ba01477 (v1 rev2)
DEBUG:pyocd.utility.sequencer:Running task clear_sticky_err
DEBUG:pyocd.utility.sequencer:Running task power_up_debug
DEBUG:pyocd.utility.sequencer:Running task check_version
DEBUG:pyocd.utility.sequencer:Running task unlock_probe
DEBUG:pyocd.utility.sequencer:Running task create_discoverer
DEBUG:pyocd.utility.sequencer:Running task discovery
DEBUG:pyocd.utility.sequencer:Running task find_aps
DEBUG:pyocd.utility.sequencer:Running task create_aps
DEBUG:pyocd.utility.sequencer:Running task create_ap.0
INFO:pyocd.coresight.ap:AHB-AP#0 IDR = 0x24770011 (AHB-AP var1 rev2)
DEBUG:pyocd.coresight.ap:AHB-AP#0 default HPROT=3 HNONSEC=0
DEBUG:pyocd.coresight.ap:AHB-AP#0 implemented HPROT=3 HNONSEC=0
DEBUG:pyocd.utility.sequencer:Running task create_ap.1
INFO:pyocd.coresight.ap:AP#1 IDR = 0x001c0000 (AP var0 rev0)
DEBUG:pyocd.utility.sequencer:Running task check_mdm_ap_idr
DEBUG:pyocd.target.family.target_kinetis:MDM-AP version 0
DEBUG:pyocd.utility.sequencer:Running task check_flash_security
INFO:pyocd.target.family.target_kinetis:K64F not in secure state
DEBUG:pyocd.utility.sequencer:Running task find_components
DEBUG:pyocd.utility.sequencer:Running task init_ap.0
INFO:pyocd.coresight.rom_table:AHB-AP#0 Class 0x1 ROM table #0 @ 0xe00ff000 (designer=43b part=4c4)
INFO:pyocd.coresight.rom_table:[0]<e000e000:SCS-M4 class=14 designer=43b part=00c>
INFO:pyocd.coresight.rom_table:[1]<e0001000:DWT class=14 designer=43b part=002>
INFO:pyocd.coresight.rom_table:[2]<e0002000:FPB class=14 designer=43b part=003>
INFO:pyocd.coresight.rom_table:[3]<e0000000:ITM class=14 designer=43b part=001>
INFO:pyocd.coresight.rom_table:[4]<e0040000:TPIU-M4 class=9 designer=43b part=9a1 devtype=11 archid=0000 devid=ca1:0:0>
INFO:pyocd.coresight.rom_table:[5]<e0041000:ETM-M4 class=9 designer=43b part=925 devtype=13 archid=0000 devid=0:0:0>
INFO:pyocd.coresight.rom_table:[6]<e0042000:ETB class=9 designer=43b part=907 devtype=21 archid=0000 devid=0:0:0>
INFO:pyocd.coresight.rom_table:[7]<e0043000:CSTF class=9 designer=43b part=908 devtype=12 archid=0000 devid=28:0:0>
DEBUG:pyocd.utility.sequencer:Running task create_cores
DEBUG:pyocd.coresight.discovery:Creating SCS-M4 component
INFO:pyocd.coresight.cortex_m:CPU core #0 is Cortex-M4 r0p1
DEBUG:pyocd.utility.sequencer:Running task create_components
DEBUG:pyocd.coresight.discovery:Creating DWT component
INFO:pyocd.coresight.dwt:4 hardware watchpoints
DEBUG:pyocd.coresight.discovery:Creating FPB component
INFO:pyocd.coresight.fpb:6 hardware breakpoints, 4 literal comparators
DEBUG:pyocd.coresight.fpb:fpb has been disabled
DEBUG:pyocd.coresight.discovery:Creating ITM component
DEBUG:pyocd.coresight.discovery:Creating TPIU-M4 component
DEBUG:pyocd.utility.sequencer:Running task check_for_cores
DEBUG:pyocd.utility.sequencer:Running task halt_on_connect
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.utility.sequencer:Running task post_connect
DEBUG:pyocd.utility.sequencer:Running task post_connect_hook
DEBUG:pyocd.utility.sequencer:Running task create_flash
DEBUG:pyocd.utility.sequencer:Running task notify
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:set reset catch, core 0
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:reset, core 0, type=SW_SYSRESETREQ
WARNING:pyocd.coresight.cortex_m:Timed out waiting for target to complete reset (state is RESET)
DEBUG:pyocd.coresight.cortex_m:clear reset catch, core 0
DEBUG:pyocd.core.session:uninit session <pyocd.core.session.Session object at 0xffff838657b8>
DEBUG:pyocd.board.board:uninit board <pyocd.board.mbed_board.MbedBoard object at 0xffff83e57358>
DEBUG:pyocd.coresight.cortex_m:cannot resume: target not halted
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:closing interface
Traceback (most recent call last):
  File "/usr/local/bin/pyocd-flashtool", line 10, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 421, in program
    self._build_sectors_and_pages(keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 319, in _build_sectors_and_pages
    fill_end_of_page_gap()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 263, in fill_end_of_page_gap
    self._enable_read_access()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 222, in _enable_read_access
    self.flash.init(self.flash.Operation.VERIFY)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 246, in init
    r0=address, r1=clock, r2=operation.value, init=True)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 584, in _call_function_and_wait
    self._call_function(pc, r0, r1, r2, r3, init)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 524, in _call_function
    self.target.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 188, in write_core_registers_raw
    self.selected_core.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1095, in write_core_registers_raw
    self._base_write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1113, in _base_write_core_registers_raw
    self.core_number))
pyocd.core.exceptions.CoreRegisterAccessError: cannot write registers pc, r0, r1, r2, r9, sp, lr because core #0 is not halted
root@pi-worker01:~# lspci -d 1106:3483 -xxx | awk '/^50:/ { print "VL805 FW version: " $5 $4 $3 $2 }'
VL805 FW version: 000138a1
root@pi-worker01:~# pyocd-flashtool -d debug -t k64f -f 3000000 --board 0240000034544e45004d00028aa900222011000097969900 zephyr.bin
WARNING:pyocd.tools.flash_tool:pyocd-flashtool is deprecated; please use the new combined pyocd tool.
DEBUG:pyocd.core.session:Project directory: /root
INFO:pyocd.board.board:Target type is k64f
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:Detaching Kernel Driver of Interface 3 from USB device (VID=0d28 PID=0204).
DEBUG:pyocd.probe.pydapaccess.dap_access_cmsis_dap:CMSIS-DAP probe 0240000034544e45004d00028aa900222011000097969900 firmware version: 1.10
DEBUG:pyocd.utility.sequencer:Running task load_svd
DEBUG:pyocd.utility.sequencer:Running task pre_connect
DEBUG:pyocd.utility.sequencer:Running task dp_init
DEBUG:pyocd.utility.sequencer:Running task lock_probe
DEBUG:pyocd.utility.sequencer:Running task get_probe_capabilities
DEBUG:pyocd.utility.sequencer:Running task connect
DEBUG:pyocd.coresight.dap:Default wire protocol selected; using SWD
DEBUG:pyocd.probe.swj:Sending deprecated SWJ sequence to select SWD
INFO:pyocd.coresight.dap:DP IDR = 0x2ba01477 (v1 rev2)
DEBUG:pyocd.utility.sequencer:Running task clear_sticky_err
DEBUG:pyocd.utility.sequencer:Running task power_up_debug
DEBUG:pyocd.utility.sequencer:Running task check_version
DEBUG:pyocd.utility.sequencer:Running task unlock_probe
DEBUG:pyocd.utility.sequencer:Running task create_discoverer
DEBUG:pyocd.utility.sequencer:Running task discovery
DEBUG:pyocd.utility.sequencer:Running task find_aps
DEBUG:pyocd.utility.sequencer:Running task create_aps
DEBUG:pyocd.utility.sequencer:Running task create_ap.0
INFO:pyocd.coresight.ap:AHB-AP#0 IDR = 0x24770011 (AHB-AP var1 rev2)
DEBUG:pyocd.coresight.ap:AHB-AP#0 default HPROT=3 HNONSEC=0
DEBUG:pyocd.coresight.ap:AHB-AP#0 implemented HPROT=3 HNONSEC=0
DEBUG:pyocd.utility.sequencer:Running task create_ap.1
INFO:pyocd.coresight.ap:AP#1 IDR = 0x001c0000 (AP var0 rev0)
DEBUG:pyocd.utility.sequencer:Running task check_mdm_ap_idr
DEBUG:pyocd.target.family.target_kinetis:MDM-AP version 0
DEBUG:pyocd.utility.sequencer:Running task check_flash_security
INFO:pyocd.target.family.target_kinetis:K64F not in secure state
DEBUG:pyocd.utility.sequencer:Running task find_components
DEBUG:pyocd.utility.sequencer:Running task init_ap.0
INFO:pyocd.coresight.rom_table:AHB-AP#0 Class 0x1 ROM table #0 @ 0xe00ff000 (designer=43b part=4c4)
INFO:pyocd.coresight.rom_table:[0]<e000e000:SCS-M4 class=14 designer=43b part=00c>
INFO:pyocd.coresight.rom_table:[1]<e0001000:DWT class=14 designer=43b part=002>
INFO:pyocd.coresight.rom_table:[2]<e0002000:FPB class=14 designer=43b part=003>
INFO:pyocd.coresight.rom_table:[3]<e0000000:ITM class=14 designer=43b part=001>
INFO:pyocd.coresight.rom_table:[4]<e0040000:TPIU-M4 class=9 designer=43b part=9a1 devtype=11 archid=0000 devid=ca1:0:0>
INFO:pyocd.coresight.rom_table:[5]<e0041000:ETM-M4 class=9 designer=43b part=925 devtype=13 archid=0000 devid=0:0:0>
INFO:pyocd.coresight.rom_table:[6]<e0042000:ETB class=9 designer=43b part=907 devtype=21 archid=0000 devid=0:0:0>
INFO:pyocd.coresight.rom_table:[7]<e0043000:CSTF class=9 designer=43b part=908 devtype=12 archid=0000 devid=28:0:0>
DEBUG:pyocd.utility.sequencer:Running task create_cores
DEBUG:pyocd.coresight.discovery:Creating SCS-M4 component
INFO:pyocd.coresight.cortex_m:CPU core #0 is Cortex-M4 r0p1
DEBUG:pyocd.utility.sequencer:Running task create_components
DEBUG:pyocd.coresight.discovery:Creating DWT component
INFO:pyocd.coresight.dwt:4 hardware watchpoints
DEBUG:pyocd.coresight.discovery:Creating FPB component
INFO:pyocd.coresight.fpb:6 hardware breakpoints, 4 literal comparators
DEBUG:pyocd.coresight.fpb:fpb has been disabled
DEBUG:pyocd.coresight.discovery:Creating ITM component
DEBUG:pyocd.coresight.discovery:Creating TPIU-M4 component
DEBUG:pyocd.utility.sequencer:Running task check_for_cores
DEBUG:pyocd.utility.sequencer:Running task halt_on_connect
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.utility.sequencer:Running task post_connect
DEBUG:pyocd.utility.sequencer:Running task post_connect_hook
DEBUG:pyocd.utility.sequencer:Running task create_flash
DEBUG:pyocd.utility.sequencer:Running task notify
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:set reset catch, core 0
DEBUG:pyocd.coresight.cortex_m:halting core 0
DEBUG:pyocd.coresight.cortex_m:reset, core 0, type=SW_SYSRESETREQ
WARNING:pyocd.coresight.cortex_m:Timed out waiting for target to complete reset (state is RESET)
DEBUG:pyocd.coresight.cortex_m:clear reset catch, core 0
DEBUG:pyocd.core.session:uninit session <pyocd.core.session.Session object at 0xffffae00ac18>
DEBUG:pyocd.board.board:uninit board <pyocd.board.mbed_board.MbedBoard object at 0xffffada15ef0>
DEBUG:pyocd.coresight.cortex_m:cannot resume: target not halted
DEBUG:pyocd.probe.pydapaccess.interface.pyusb_backend:closing interface
Traceback (most recent call last):
  File "/usr/local/bin/pyocd-flashtool", line 10, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/dist-packages/pyocd/tools/flash_tool.py", line 219, in main
    skip=args.skip)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/file_programmer.py", line 158, in program
    self._loader.commit()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/loader.py", line 168, in commit
    keep_unwritten=self._keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 421, in program
    self._build_sectors_and_pages(keep_unwritten)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 319, in _build_sectors_and_pages
    fill_end_of_page_gap()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 263, in fill_end_of_page_gap
    self._enable_read_access()
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/builder.py", line 222, in _enable_read_access
    self.flash.init(self.flash.Operation.VERIFY)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 246, in init
    r0=address, r1=clock, r2=operation.value, init=True)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 584, in _call_function_and_wait
    self._call_function(pc, r0, r1, r2, r3, init)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/flash/flash.py", line 524, in _call_function
    self.target.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/core/soc_target.py", line 188, in write_core_registers_raw
    self.selected_core.write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1095, in write_core_registers_raw
    self._base_write_core_registers_raw(reg_list, data_list)
  File "/usr/local/lib/python3.7/dist-packages/pyocd/coresight/cortex_m.py", line 1113, in _base_write_core_registers_raw
    self.core_number))
pyocd.core.exceptions.CoreRegisterAccessError: cannot write registers pc, r0, r1, r2, r9, sp, lr because core #0 is not halted
pfalcon commented 3 years ago

Experiment 1: Try to vary SWD frequency, which had some effect in earlier pyocd 0.13.1 experiments:

pyocd-flashtool -d debug -t k64f -f 1500000 --board 0240000034544e45004d00028aa900222011000097969900 zephyr.bin
pyocd-flashtool -d debug -t k64f -f 2000000 --board 0240000034544e45004d00028aa900222011000097969900 zephyr.bin

Doesn't have any effect now. What happens is that pyocd reaches the log line:

DEBUG:pyocd.coresight.cortex_m:reset, core 0, type=SW_SYSRESETREQ

Then pauses, the continues with:

WARNING:pyocd.coresight.cortex_m:Timed out waiting for target to complete reset (state is RESET)

and the rest of error.

Idea: pyocd support different reset types, try to vary among them.

pfalcon commented 3 years ago

Tried (based on pyocd --help-options | grep reset_type):

pyocd-flashtool -d debug -t k64f -f 3000000 -O reset_type=hw --board 0240000034544e45004d00028aa900222011000097969900 zephyr.bin

But that doesn't seem to have any difference - it still says 0003715:DEBUG:cortex_m:reset, core 0, type=SW_SYSRESETREQ. Actually, using invalid option value, like -O reset_type=h2w also doesn't have any effect. Likewise, using invalid option name in -O doesn't have any effect either. I also tried "pyocd flash" command instead.

pfalcon commented 3 years ago

Posted https://github.com/pyocd/pyOCD/issues/1103 and https://github.com/pyocd/pyOCD/issues/1042#issuecomment-788120691 on that.

pfalcon commented 3 years ago

Now trying

  -M MODE, --connect MODE
                        Select connect mode from one of (halt, pre-reset,
                        under-reset, attach).

to pyocd flash (not available for older pyocd-flashtool).

# pyocd flash -v -v -t k64f -f 3000000 -M halt zephyr.bin
# pyocd flash -v -v -t k64f -f 3000000 -M pre-reset zephyr.bin

- no difference

# pyocd flash -v -v -t k64f -f 3000000 -M under-reset zephyr.bin

- this worked!

After that, it works even without -M switch. (Of course, until next time it's stuck at that state.)

pfalcon commented 3 years ago

On slack, @galak wrote:

@Paul Sokolovsky you can try: pyocd cmd -c show locked and if locked you can try: pyocd cmd -c unlock

So, we now have the labs board stuck in its usual state:

# pyocd flash -v -v -t k64f -f 3000000 zephyr.bin
...
pyocd.core.exceptions.CoreRegisterAccessError: cannot write registers pc, r0, r1, r2, r9, sp, lr because core #0 is not halted
# pyocd flash -v -v -t k64f -f 3000000 zephyr.bin
...
pyocd.core.exceptions.CoreRegisterAccessError: cannot write registers pc, r0, r1, r2, r9, sp, lr because core #0 is not halted

Running the command above:

# pyocd cmd -c show locked
0001871:WARNING:target_kinetis:Forcing halt on connect in order to gain control of device
Taget is unlocked

However, after it, flash command indeed went ahead, though this particular time it USB timed out:

root@pi-worker01:~# pyocd flash -v -v -t k64f -f 3000000 zephyr.bin
...
[========            ]  45%0004496:DEBUG:cortex_m:resuming core 0
...
usb.core.USBError: [Errno 110] Operation timed out

So, bottom line, it's possible to reset the board from that weird state, we just need to find the most reliable and most practical way to do that with LAVA (across different pyocd versions), which requires more experimenting.

pfalcon commented 3 years ago

Ok, by now I confirmed (on 2 cases ;-) ) that passing -M under-reset zephyr.bin to pyocd flash resets the board from the stuck state. The issue, -M switch is not available in pyocd-flashtool, which we need to maintain compatibility with older pyocd versions (0.13.1 didn't have pyocd command).

Beyond that, the board still may be stuck in "USB timeout at ~50% of flashing process" state, but from that it seems to recover with USB hub reset command (using uhubctl). Note that currentlyuhubctl is only executed in health jobs, not normal job.

So, that's the current hypothesis, I'll be looking to confirm it on more stuck cases, and way to encode it in LAVA.