nrf5340DK debugger restarts, port disconnected

[Niklas Parnesten]

nrfjprog restarts nrf5340DK debugger

We are running a container environment in Ubuntu 20.04 on WSL2 and the USB ports are frwarded using usbipd

When trying to flash (or just reset) the nrf5340DK after connecting and disconnecting a terminal emulator program
the debugger chip seems to be restarting and the port is lost to the container.

This means we have to connect the ports again and restart the container, making it impossible to run automatic tests for instance

Steps to recreate:
1. Build the zephyr/samples/hello_world sample for nrf5340dk_nrf5340_cpuapp
2. flash the board with nrfjprog
3. Open a terminal emulator program (putty and picocom tested)
4. Reset the board to se the printout
5. Exit the terminal emulator program
6. Try to flash: the following error occurs:

ERROR: Unable to connect to a debugger.
ERROR: [SeggerBackend] - JLinkARM.dll Open returned error 'Cannot connect to J-Link.'
ERROR: [SeggerBackend] - JLinkARM.dll Open returned error 'Failed to open DLL'
ERROR: JLinkARM DLL reported an error. Try again. If error condition
ERROR: persists, run the same command again with argument --log, contact Nordic
ERROR: Semiconductor and provide the generated log.log file to them.

The we need to connect the port again in WSL and the restart the container to get it working again.

The question is, why do we end up in this state after using the emulator and is it possible to flash without resetting the debugger?

See attached log files

Environment:
nrfjprog: 10.15.2
jLink: DLL version V7.62a, compiled Feb 23 2022 17:02:35
Firmware: J-Link OB-nRF5340-NordicSemi compiled Dec 3 2021 15:46:49

Hardware: PCA10095 2.0.0

Log from when it fails:

Fullscreen 5824.nrfjprog_nrf5340_NOK.txt Download

[2022-Feb-25 16:04:53] [ info] --------------------------------------------------------------------------------
[2022-Feb-25 16:04:53] [ info] nrfjprog --program build/zephyr/hello_zephyr.hex --recover --verify -f NRF53 --log 
[2022-Feb-25 16:04:53] [ info] nrfjprog version 10.15.2 external
[2022-Feb-25 16:04:53] [ info] --------------------------------------------------------------------------------
[2022-Feb-25 16:04:53] [ info] Load library at /opt/nrf-command-line-tools/lib/libnrfjprogdll.so.
[2022-Feb-25 16:04:53] [ info] Library loaded, loading member functions.
[2022-Feb-25 16:04:53] [ info] Member functions succesfully loaded.
[2022-Feb-25 16:04:53] [debug] [ Client] - open
[2022-Feb-25 16:04:53] [debug] [ Client] - start
[2022-Feb-25 16:04:53] [ info] [ Client] - stdout: Jlinkarm nRF Worker ready. Handling sequence 0fb58d33-9d91-434f-81c7-7d68de21c7a9.
[2022-Feb-25 16:04:53] [trace] [ Client] - Command open executed for 2 milliseconds with result 0
[2022-Feb-25 16:04:53] [debug] [ Client] - enum_emu_snr
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - Logger sink registered in Segger backend logger
[2022-Feb-25 16:04:53] [debug] [  JLink] - Logger sink registered in JLink logger
[2022-Feb-25 16:04:53] [debug] [  nRF53] - open
[2022-Feb-25 16:04:53] [debug] [  nRF53] - just_check_family
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - open_dll
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - No J-Link DLL path was provided. Attempting to auto detect.
[2022-Feb-25 16:04:53] [ info] [SeggerBackend] - Load library at /opt/SEGGER/JLink/libjlinkarm.so.7.
[2022-Feb-25 16:04:53] [ info] [SeggerBackend] - Library loaded, loading member functions.
[2022-Feb-25 16:04:53] [ info] [SeggerBackend] - Member functions succesfully loaded.
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - dll_version
[2022-Feb-25 16:04:53] [ info] [SeggerBackend] - Segger dll version 7.62.a loaded.
[2022-Feb-25 16:04:53] [trace] [ Worker] - Command open executed for 1 milliseconds with result 0
[2022-Feb-25 16:04:53] [debug] [  nRF53] - enum_emu_con_info
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - is_connected_to_emu
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - enum_emu_con_info
[2022-Feb-25 16:04:53] [trace] [ Client] - Command enum_emu_con_info executed for 32 milliseconds with result 0
[2022-Feb-25 16:04:53] [debug] [ Client] - connect_to_emu_with_snr
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - is_connected_to_emu
[2022-Feb-25 16:04:53] [trace] [ Worker] - Command enum_emu_con_info executed for 32 milliseconds with result 0
[2022-Feb-25 16:04:53] [debug] [  nRF53] - connect_to_emu_with_snr
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - is_connected_to_emu
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - connect_to_emu_with_snr
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - is_connected_to_emu
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - ---just_enum_emu_snr
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - ---just_get_num_emus
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - ---just_connect_to_emu_with_snr
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - ---just_connect_to_emu_without_snr
[2022-Feb-25 16:04:53] [debug] [SeggerBackend] - Segger logging enabled.
[2022-Feb-25 16:05:01] [trace] [ Client] - Command connect_to_emu_with_snr executed for 8177 milliseconds with result -102
[2022-Feb-25 16:05:01] [trace] [  JLink] -    ***** Error: 
[2022-Feb-25 16:05:01] [trace] [  JLink] - Cannot connect to J-Link.
[2022-Feb-25 16:05:01] [trace] [  JLink] - - 8061.153ms returns "Cannot connect to J-Link."  
[2022-Feb-25 16:05:01] [trace] [  JLink] - JLINK_HasError()  
[2022-Feb-25 16:05:01] [error] [SeggerBackend] - JLinkARM.dll Open returned error 'Cannot connect to J-Link.'
[2022-Feb-25 16:05:01] [trace] [  JLink] - JLINK_OpenEx(...)  
[2022-Feb-25 16:05:01] [trace] [  JLink] - - 0.053ms returns "Failed to open DLL"  
[2022-Feb-25 16:05:01] [trace] [  JLink] - JLINK_HasError()  
[2022-Feb-25 16:05:01] [error] [SeggerBackend] - JLinkARM.dll Open returned error 'Failed to open DLL'
[2022-Feb-25 16:05:01] [debug] [SeggerBackend] - is_connected_to_emu
[2022-Feb-25 16:05:01] [trace] [  JLink] - JLINK_IsOpen()  
[2022-Feb-25 16:05:01] [trace] [  JLink] - - 0.003ms returns 0x00  
[2022-Feb-25 16:05:01] [trace] [  JLink] - JLINK_HasError()  
[2022-Feb-25 16:05:01] [trace] [ Worker] - Command connect_to_emu_with_snr executed for 8177 milliseconds with result -102
[2022-Feb-25 16:05:01] [debug] [  nRF53] - close
[2022-Feb-25 16:05:01] [debug] [SeggerBackend] - is_connected_to_emu
[2022-Feb-25 16:05:01] [trace] [  JLink] - JLINK_IsOpen()  
[2022-Feb-25 16:05:01] [trace] [  JLink] - - 0.006ms returns 0x00  
[2022-Feb-25 16:05:01] [trace] [  JLink] - JLINK_HasError()  
[2022-Feb-25 16:05:01] [debug] [SeggerBackend] - close
[2022-Feb-25 16:05:01] [debug] [SeggerBackend] - disconnect_from_emu
[2022-Feb-25 16:05:01] [debug] [SeggerBackend] - is_connected_to_emu
[2022-Feb-25 16:05:01] [trace] [  JLink] - JLINK_IsOpen()  
[2022-Feb-25 16:05:01] [trace] [  JLink] - - 0.003ms returns 0x00  
[2022-Feb-25 16:05:01] [trace] [  JLink] - JLINK_HasError()  
[2022-Feb-25 16:05:01] [debug] [SeggerBackend] - Segger Backend closed.
[2022-Feb-25 16:05:01] [debug] [  nRF53] - nRF family DLL closed
[2022-Feb-25 16:05:01] [trace] [ Client] - Command close executed for 10 milliseconds with result 0
[2022-Feb-25 16:05:01] [debug] [ Client] - terminate
[2022-Feb-25 16:05:01] [trace] [ Client] - Command terminate executed for 0 milliseconds with result 0
[2022-Feb-25 16:05:01] [trace] [ Worker] - Command close executed for 10 milliseconds with result 0
[2022-Feb-25 16:05:01] [trace] [ Worker] - Command terminate executed for 0 milliseconds with result 0
[2022-Feb-25 16:05:01] [trace] [ Worker] - Executed 5 commands for 8220 milliseconds
[2022-Feb-25 16:05:01] [debug] [ Client] - Child process terminated with result 0
[2022-Feb-25 16:05:01] [debug] [ Client] - Worker process exited with code: 0
[2022-Feb-25 16:05:01] [debug] [ Client] - Worker process exited with code: 0
[2022-Feb-25 16:05:01] [trace] [ Client] - Executed 5 commands for 8221 milliseconds
[2022-Feb-25 16:05:01] [debug] [ Client] - terminate

Log from when it works:

8156.nrfjprog_nrf5340_OK.txt

investigation.zip

[Håkon Alseth]

Hi,

 

We are running a container environment in Ubuntu 20.04 on WSL2 and the USB ports are forwarded using usbipd

This is a setup that is not tested from our side and known to be prone to connectivity errors like you're seeing. I am not saying that the issue cannot be with jlink/nrfjprog, especially since you are running the newer DK with a nRF5340 interface MCU, but we'll need to dig a bit deeper here to see where in the chain that the issue occurs.

I am unfortunately not able to reproduce this, with either pca10095 v0.12.0 or v2.0.0, when running on a native OS.

The we need to connect the port again in WSL and the restart the container to get it working again.

Q1: Is this occurring every time at your end? Or is it like 1 out of 10 runs that fail?

Q2: does "dmesg" give any indication on what happened?

Q3: Do other DK's also behave like this, or is this specific to the nRF5340-DK v2.0.0 ?

 

nrfjprog: 10.15.2
jLink: DLL version V7.62a, compiled Feb 23 2022 17:02:35
Firmware: J-Link OB-nRF5340-NordicSemi compiled Dec 3 2021 15:46:49

Q4: Have you tried using the bundled jlink versions in nrf command line tools (where nrfjprog is also found)?

 

Kind regards,

Håkon

[Niklas Parnesten]

Håkon Alseth said:

Q1: Is this occurring every time at your end? Or is it like 1 out of 10 runs that fail?

Yes, every time

Håkon Alseth said:

Q2: does "dmesg" give any indication on what happened?

There seem to be a error:

" vhci_hcd: cannot find a urb of seqnum 58679 max seqnum 58686"

attaching a file with the sequence

Fullscreen dmesg.txt Download

[20032.854512] vhci_hcd vhci_hcd.0: pdev(0) rhport(0) sockfd(3)
[20032.854515] vhci_hcd vhci_hcd.0: devid(524290) speed(2) speed_str(full-speed)
[20032.854548] vhci_hcd vhci_hcd.0: Device attached
[20033.131604] vhci_hcd: vhci_device speed not set
[20033.201641] usb 1-1: new full-speed USB device number 15 using vhci_hcd
[20033.281600] vhci_hcd: vhci_device speed not set
[20033.351639] usb 1-1: SetAddress Request (15) to port 0
[20033.397017] usb 1-1: New USB device found, idVendor=1366, idProduct=1051, bcdDevice= 1.00
[20033.397019] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[20033.397019] usb 1-1: Product: J-Link
[20033.397020] usb 1-1: Manufacturer: SEGGER
[20033.397040] usb 1-1: SerialNumber: 001050009857
[20033.400006] cdc_acm 1-1:1.0: ttyACM0: USB ACM device
[20033.401606] cdc_acm 1-1:1.2: ttyACM1: USB ACM device
[20036.319549] docker0: port 1(vethdc3882f) entered disabled state
[20036.319586] vethad765cf: renamed from eth0
[20036.459355] docker0: port 1(vethdc3882f) entered disabled state
[20036.460745] device vethdc3882f left promiscuous mode
[20036.460764] docker0: port 1(vethdc3882f) entered disabled state
[20036.587806] docker0: port 1(veth0ad84f8) entered blocking state
[20036.587808] docker0: port 1(veth0ad84f8) entered disabled state
[20036.587831] device veth0ad84f8 entered promiscuous mode
[20036.587926] docker0: port 1(veth0ad84f8) entered blocking state
[20036.587927] docker0: port 1(veth0ad84f8) entered forwarding state
[20036.872224] eth0: renamed from veth9254cd7
[20036.921875] IPv6: ADDRCONF(NETDEV_CHANGE): veth0ad84f8: link becomes ready
[20162.232266] vhci_hcd: unlink->seqnum 58654
[20162.232297] vhci_hcd: the urb (seqnum 58654) was already given back
[20162.235319] vhci_hcd: unlink->seqnum 58655
[20162.235320] vhci_hcd: the urb (seqnum 58655) was already given back
[20162.235412] vhci_hcd: unlink->seqnum 58656
[20162.235413] vhci_hcd: the urb (seqnum 58656) was already given back
[20162.235413] vhci_hcd: unlink->seqnum 58657
[20162.235414] vhci_hcd: the urb (seqnum 58657) was already given back
[20162.235415] vhci_hcd: unlink->seqnum 58658
[20162.235415] vhci_hcd: the urb (seqnum 58658) was already given back
[20162.235431] vhci_hcd: unlink->seqnum 58659
[20162.235499] vhci_hcd: the urb (seqnum 58659) was already given back
[20162.235503] vhci_hcd: unlink->seqnum 58660
[20162.235504] vhci_hcd: the urb (seqnum 58660) was already given back
[20162.235554] vhci_hcd: unlink->seqnum 58661
[20162.235554] vhci_hcd: the urb (seqnum 58661) was already given back

*** Serial emulator disconnected, trying to flash again:
[20194.302157] vhci_hcd: unlink->seqnum 58680
[20194.302160] vhci_hcd: urb->status 0
[20195.342026] vhci_hcd: unlink->seqnum 58682
[20195.342029] vhci_hcd: urb->status 0
[20196.271058] vhci_hcd: cannot find a urb of seqnum 58679 max seqnum 58686
[20196.271279] vhci_hcd: stop threads
[20196.271280] vhci_hcd: release socket
[20196.271281] vhci_hcd: unlink cleanup rx 58664
[20196.271281] vhci_hcd: the urb (seqnum 58664) was already given back
[20196.271282] vhci_hcd: unlink cleanup rx 58667
[20196.271282] vhci_hcd: the urb (seqnum 58667) was already given back
[20196.271283] vhci_hcd: unlink cleanup rx 58678
[20196.271283] vhci_hcd: the urb (seqnum 58678) was already given back
[20196.271336] vhci_hcd: disconnect device
[20196.271425] usb 1-1: USB disconnect, device number 15

Håkon Alseth said:

Q3: Do other DK's also behave like this, or is this specific to the nRF5340-DK v2.0.0 ?

nRF52840DK does NOT have this behavior, it works as expected.

I have also tried using a external jlink debugger on the nrf5340 and it works without any problems

Håkon Alseth said:

Q4: Have you tried using the bundled jlink versions in nrf command line tools (where nrfjprog is also found)?

Yes, I started with this:

https://www.nordicsemi.com/-/media/Software-and-other-downloads/Desktop-software/nRF-command-line-tools/sw/Versions-10-x-x/10-15-2/nrf-command-line-tools-10.15.2_Linux-amd64.zip

I tried to update the Jlink after I discovered the problem.

Best Regards,

Niklas