pyocd-gdbserver crash when disconnecting serial port

jupe commented 7 years ago

If I start pyocd-gdbserver, run application and open serial port connection to mbed (K64F) board everything seems work as expected, but if I then disconnect serial port pyocd-gdbserver crashes with Unhandled exception in handleMsg.

See traceback below:

2017-05-17T11:55:03.547Z - warn: pyocd:stderr:  ERROR:root:Unhandled exception in handleMsg: 
2017-05-17T11:55:03.547Z - warn: pyocd:stderr:  Traceback (most recent call last):
2017-05-17T11:55:03.547Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/gdbserver/gdbserver.py", line 426, in handleMsg
2017-05-17T11:55:03.547Z - warn: pyocd:stderr:      return self.getRegisters(), 0
2017-05-17T11:55:03.547Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/gdbserver/gdbserver.py", line 868, in getRegisters
2017-05-17T11:55:03.547Z - warn: pyocd:stderr:      return self.createRSPPacket(self.target_facade.getRegisterContext())
2017-05-17T11:55:03.547Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/gdbserver/context_facade.py", line 54, in getRegisterContext
2017-05-17T11:55:03.547Z - warn: pyocd:stderr:      vals = self._context.readCoreRegistersRaw(reg_num_list)
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/debug/context.py", line 117, in readCoreRegistersRaw
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:      return self._core.readCoreRegistersRaw(reg_list)
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/coresight/cortex_m.py", line 655, in readCoreRegistersRaw
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:      reg_cb = self.readMemory(CortexM.DCRDR, now=False)
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/coresight/cortex_m.py", line 397, in readMemory
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:      result = self.ap.readMemory(addr, transfer_size, now)
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/coresight/ap.py", line 162, in readMemory
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:      self.write_reg(AP_REG['TAR'], addr)
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/coresight/ap.py", line 103, in write_reg
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:      self.dp.writeAP((self.ap_num << APSEL_SHIFT) | addr, data)
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/coresight/dap.py", line 259, in writeAP
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:      self.link.write_reg(ap_reg, data)
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/pyDAPAccess/dap_access_cmsis_dap.py", line 635, in write_reg
2017-05-17T11:55:03.548Z - warn: pyocd:stderr:      self._write(dap_index, 1, request, [value])
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/pyDAPAccess/dap_access_cmsis_dap.py", line 840, in _write
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:      self._send_packet()
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/pyDAPAccess/dap_access_cmsis_dap.py", line 783, in _send_packet
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:      self._read_packet()
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/pyDAPAccess/dap_access_cmsis_dap.py", line 738, in _read_packet
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:      decoded_data = cmd.decode_data(raw_data)
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/pyDAPAccess/dap_access_cmsis_dap.py", line 419, in decode_data
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:      data = self._decode_transfer_data(data)
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:    File "/Users/user01/git/github/mbedmicro/pyOCD/pyOCD/pyDAPAccess/dap_access_cmsis_dap.py", line 318, in _decode_transfer_data
2017-05-17T11:55:03.549Z - warn: pyocd:stderr:      raise DAPAccessIntf.TransferError()
2017-05-17T11:55:03.551Z - warn: pyocd:stderr:  TransferErro

flit commented 7 years ago

I presume you are using DAPLink on the K64F board? Which version?

This actually sounds like a DAPLink bug rather than pyOCD. There should be no connection between the CDC and CMSIS-DAP interfaces.

Regardless, pyOCD should perhaps more gracefully handle the transfer error.

jupe commented 7 years ago

Daplink was 0242 or 0243, I can check it out. yes root cause could be in daplink side as well. I also saw some strange data appears to serial port when I pause debugging, probably related (also) to daplink.

flit commented 7 years ago

Double checking the version would be good. There were a number of USB related fixes in DAPLink 0243.

jupe commented 7 years ago

# DAPLink Firmware - see https://mbed.com/daplink
Unique ID: 0240000033514e450031500585d40022e981000097969900
HIC ID: 97969900
Auto Reset: 0
Automation allowed: 1
Overflow detection: 0
Daplink Mode: Interface
Interface Version: 0243
Bootloader Version: 0242
Git SHA: b403a07e3696cee1e116d44cbdd64446e056ce38
Local Mods: 0
USB Interfaces: MSD, CDC, HID
Bootloader CRC: 0xa65218eb
Interface CRC: 0x4d98bf7e
Remount count: 0

c1728p9 commented 7 years ago

DAPLink interprets a serial break as a command to reset the target. This is used extensively by mbed testing. This is the only command I would expect to interfere with the serial port, and that shouldn't be getting sent on disconnect.

flit commented 7 years ago

Ah, wait a sec. On macOS, when you disconnect from a serial port, it does in fact automatically send a break (which is a real pain when using DAPLink for testing). I wonder if this is a POSIX thing?

@jupe What OS are you using?

jupe commented 7 years ago

mac 🙄😐

c1728p9 commented 7 years ago

I just tried this on my machine locally. I don't see the break being sent on windows when closing the serial terminal. Also, if I intentionally send a break from the serial terminal I get a traceback similar to what you got.

flit commented 7 years ago

Right, the break on close is only sent on macOS.

Two suggestions here:

It might be nice the have a configuration setting to disable the reset-on-break feature of DAPLink.
pyOCD needs to detect the target unexpectedly going into reset. This could be helped by extending CMSIS-DAP/DAPLink to send a notification of a detected reset.

SeppoTakalo commented 6 years ago

I have now verified this with current PyOCD and the issue still exist. Can you at least workaround this?

I'm forced to use OpenOCD to debug the Icetea testcases, since it does not crash. Only stops the debugging session. But if I'm fast enough, I can call continue on GDB immeadiately when it happens and the testcase continues..

flit commented 6 years ago

Thanks for the update @SeppoTakalo. I'll try to reproduce it. But it will take some time to get to due to priorities related to Mbed Studio for TechCon.

I'd like to approach this from several angles:

Add option to DAPLink to disable reset-on-break.
Make pyOCD more resilient to transfer errors. This is likely to be a complex task.
Research what code in the Mac serial stack is sending the break on connection code, and if there's a way to disable it. I've previously searched for info about this online (several years ago) but nothing came up. I'll probably have to dig into the serial driver Kext code or BSD serial support (which is thankfully all open source).

jupe commented 5 years ago

Tried with #455 branch but this still reproduces:

$ pyocd-gdbserver 
0000427:INFO:board:Target type is k64f
0000470:INFO:dap:DP IDR = 0x2ba01477
0000487:INFO:dap:AP#0 IDR = 0x24770011
0000494:INFO:dap:AP#1 IDR = 0x001c0000
0000520:INFO:target_kinetis:K64F not in secure state
0000531:INFO:rom_table:AP#0 ROM table #0 @ 0xe00ff000 (designer=43b part=4c4)
0000539:INFO:rom_table:[0]<e000e000:SCS-M4 class=14 designer=43b part=00c>
0000545:INFO:rom_table:[1]<e0001000:DWT class=14 designer=43b part=002>
0000551:INFO:rom_table:[2]<e0002000:FPB class=14 designer=43b part=003>
0000558:INFO:rom_table:[3]<e0000000:ITM class=14 designer=43b part=001>
0000564:INFO:rom_table:[4]<e0040000:TPIU-M4 class=9 designer=43b part=9a1 devtype=11 archid=0000 devid=0:0:ca1>
0000571:INFO:rom_table:[5]<e0041000:ETM-M4 class=9 designer=43b part=925 devtype=13 archid=0000 devid=0:0:0>
0000577:INFO:rom_table:[6]<e0042000:ETB class=9 designer=43b part=907 devtype=21 archid=0000 devid=0:0:0>
0000583:INFO:rom_table:[7]<e0043000:CSTF class=9 designer=43b part=908 devtype=12 archid=0000 devid=0:0:28>
0000588:INFO:cortex_m:CPU core is Cortex-M4 r0p1
0000593:INFO:cortex_m:FPU present
0000609:INFO:dwt:4 hardware watchpoints
0000612:INFO:fpb:6 hardware breakpoints, 4 literal comparators
0000623:INFO:semihost:Telnet: server started on port 54356
0000624:INFO:gdbserver:GDB server started at port:3333
0009058:INFO:gdbserver:One client connected!
Traceback (most recent call last):
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 729, in resume
    self.target.halt()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 527, in halt
    self.flush()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/core/target.py", line 109, in flush
    self.session.probe.flush()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/probe/cmsis_dap_probe.py", line 226, in flush
    six.raise_from(self._convert_exception(exc), exc)
  File "/usr/local/lib/python2.7/site-packages/six.py", line 737, in raise_from
    raise value
TransferError
0018060:ERROR:gdbserver:Unhandled exception in handle_message: 
Traceback (most recent call last):
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 546, in handle_message
    reply = handler(msg[msgStart:])
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 767, in v_command
    return self.v_cont(cmd)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 818, in v_cont
    return self.resume(None)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 734, in resume
    val = ('S%02x' % self.target_facade.get_signal_value()).encode()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/context_facade.py", line 117, in get_signal_value
    if self._context.core.is_debug_trap():
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 946, in is_debug_trap
    debugEvents = self.read_memory(CortexM.DFSR) & (CortexM.DFSR_DWTTRAP | CortexM.DFSR_BKPT | CortexM.DFSR_HALTED)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 482, in read_memory
    result = self.ap.read_memory(addr, transfer_size, now)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 312, in _read_memory
    result = read_mem_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 293, in read_mem_cb
    res = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/dap.py", line 281, in read_ap_cb
    result = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/probe/cmsis_dap_probe.py", line 293, in read_ap_result_callback
    six.raise_from(self._convert_exception(error), error)
  File "/usr/local/lib/python2.7/site-packages/six.py", line 737, in raise_from
    raise value
TransferError
0018067:ERROR:gdbserver:Unhandled exception in handle_message: 
Traceback (most recent call last):
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 544, in handle_message
    reply = handler()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 980, in get_registers
    return self.create_rsp_packet(self.target_facade.get_register_context())
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/context_facade.py", line 55, in get_register_context
    vals = self._context.read_core_registers_raw(reg_num_list)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/debug/cache.py", line 518, in read_core_registers_raw
    return self._regcache.read_core_registers_raw(reg_list)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/debug/cache.py", line 129, in read_core_registers_raw
    self._check_cache()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/debug/cache.py", line 106, in _check_cache
    if self._context.core.is_running():
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 671, in is_running
    return self.get_state() == Target.TARGET_RUNNING
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 648, in get_state
    dhcsr = self.read_memory(CortexM.DHCSR)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 482, in read_memory
    result = self.ap.read_memory(addr, transfer_size, now)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 312, in _read_memory
    result = read_mem_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 293, in read_mem_cb
    res = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/dap.py", line 281, in read_ap_cb
    result = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/probe/cmsis_dap_probe.py", line 293, in read_ap_result_callback
    six.raise_from(self._convert_exception(error), error)
  File "/usr/local/lib/python2.7/site-packages/six.py", line 737, in raise_from
    raise value
TransferError
0018072:ERROR:gdbserver:Unhandled exception in handle_message: 
Traceback (most recent call last):
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 544, in handle_message
    reply = handler()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 980, in get_registers
    return self.create_rsp_packet(self.target_facade.get_register_context())
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/context_facade.py", line 55, in get_register_context
    vals = self._context.read_core_registers_raw(reg_num_list)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/debug/cache.py", line 518, in read_core_registers_raw
    return self._regcache.read_core_registers_raw(reg_list)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/debug/cache.py", line 129, in read_core_registers_raw
    self._check_cache()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/debug/cache.py", line 106, in _check_cache
    if self._context.core.is_running():
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 671, in is_running
    return self.get_state() == Target.TARGET_RUNNING
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 648, in get_state
    dhcsr = self.read_memory(CortexM.DHCSR)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 482, in read_memory
    result = self.ap.read_memory(addr, transfer_size, now)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 312, in _read_memory
    result = read_mem_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 293, in read_mem_cb
    res = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/dap.py", line 281, in read_ap_cb
    result = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/probe/cmsis_dap_probe.py", line 293, in read_ap_result_callback
    six.raise_from(self._convert_exception(error), error)
  File "/usr/local/lib/python2.7/site-packages/six.py", line 737, in raise_from
    raise value
TransferError
0018077:ERROR:gdbserver:Unhandled exception in handle_message: 
Traceback (most recent call last):
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 544, in handle_message
    reply = handler()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/gdbserver.py", line 980, in get_registers
    return self.create_rsp_packet(self.target_facade.get_register_context())
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/gdbserver/context_facade.py", line 55, in get_register_context
    vals = self._context.read_core_registers_raw(reg_num_list)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/debug/cache.py", line 518, in read_core_registers_raw
    return self._regcache.read_core_registers_raw(reg_list)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/debug/cache.py", line 129, in read_core_registers_raw
    self._check_cache()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/debug/cache.py", line 106, in _check_cache
    if self._context.core.is_running():
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 671, in is_running
    return self.get_state() == Target.TARGET_RUNNING
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 648, in get_state
    dhcsr = self.read_memory(CortexM.DHCSR)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 482, in read_memory
    result = self.ap.read_memory(addr, transfer_size, now)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 312, in _read_memory
    result = read_mem_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 293, in read_mem_cb
    res = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/dap.py", line 281, in read_ap_cb
    result = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/probe/cmsis_dap_probe.py", line 293, in read_ap_result_callback
    six.raise_from(self._convert_exception(error), error)
  File "/usr/local/lib/python2.7/site-packages/six.py", line 737, in raise_from
    raise value
TransferError
^C0024373:ERROR:board:link exception during target disconnect:
Traceback (most recent call last):
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/board/board.py", line 58, in uninit
    self.target.disconnect(resume)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/core/coresight_target.py", line 148, in disconnect
    core.disconnect(resume)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 405, in disconnect
    self.resume()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 680, in resume
    if self.get_state() != Target.TARGET_HALTED:
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 648, in get_state
    dhcsr = self.read_memory(CortexM.DHCSR)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/cortex_m.py", line 482, in read_memory
    result = self.ap.read_memory(addr, transfer_size, now)
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 312, in _read_memory
    result = read_mem_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/ap.py", line 293, in read_mem_cb
    res = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/coresight/dap.py", line 281, in read_ap_cb
    result = result_cb()
  File "/Users/git/github/mbedmicro/pyOCD/pyocd/probe/cmsis_dap_probe.py", line 293, in read_ap_result_callback
    six.raise_from(self._convert_exception(error), error)
  File "/usr/local/lib/python2.7/site-packages/six.py", line 737, in raise_from
    raise value
TransferError

This is what I did with gdb:

(gdb) target remote localhost:3333
Remote debugging using localhost:3333
warning: Architecture rejected target-supplied description
warning: No executable has been specified and target does not support
determining executable automatically.  Try using the "file" command.
0x00000000 in ?? ()
(gdb) c
Continuing.
warning: Remote failure reply: E01
Remote failure reply: E01
Remote failure reply: E01
Remote failure reply: E01
(gdb)

just open serial port during gdb session and then closing causes this exception.

Note that this also looks like blocker for test beds

CC: @kjbracey-arm

pyocd / pyOCD

pyocd-gdbserver crash when disconnecting serial port #309