Dtmcontrol_scan stuck in infinite loop

Target board is LoFive-R1, schematic and layout. Only seven wires are connected to the jtag (Olimex) module: +5Vin, GND, TRSTN, TCK, TDO, TMS, and TDI.

Although IDCODE is successfully read,
Info : JTAG tap: riscv.cpu tap/device found: 0x20000913 (mfg: 0x489 (SiFive Inc), part: 0x0000, ver: 0x2)

further commands fail because
Warn : target riscv.cpu.0 examination failed

From the debug log, after seeing

Debug: riscv.c riscv_examine(): riscv_examine()
Debug: riscv.c dtmcontrol_scan(): DTMCONTROL: 0x0 -> 0x5071

and

Debug:  riscv-013.c init_target(): init
Debug:  riscv-013.c dtmcontrol_scan(): DTMCS: 0x0 -> 0x5071

there’s an infinite loop repeting these three steps:

Debug: riscv-013.c increase_dmi_busy_delay(): dtmcs_idle=5, dmi_busy_delay=1, ac_busy_delay=0
Debug: riscv-013.c dtmcontrol_scan(): DTMCS: 0x10000 -> 0x5471
Debug: riscv-013.c scan(): 41b - 00000000 @11 -> b 00000000 @00; 1i

The command line is:
openocd -d3 -f interface/ftdi/olimex-arm-usb-tiny-h.cfg -f fe310.cfg

The fe310.cfg file is as follows, and the entire output log from openocd is below it:

gdb_port disabled
tcl_port disabled
telnet_port disabled

transport select jtag

jtag newtap riscv cpu -irlen 5 -expected-id 0x20000913 -ignore-version -ignore-bypass ;# -ircapture 0x01 -irmask 0x1f

target create riscv.cpu.0 riscv -chain-position riscv.cpu -coreid 0

riscv.cpu.0 configure -work-area-phys 0x80000000 -work-area-size 0x10000 -work-area-backup 0

adapter speed 500
reset_config none
init
shutdown
exit

The output log is as follows:

d:\>openocd -d3 -f interface/ftdi/olimex-arm-usb-tiny-h.cfg -f fe310.cfg
xPack OpenOCD x86_64 Open On-Chip Debugger 0.11.0+dev (2022-09-01-17:58)
Licensed under GNU GPL v2
For bug reports, read
        http://openocd.org/doc/doxygen/bugs.html
User : 3 14 options.c:52 configuration_output_handler(): debug_level: 3
User : 4 23 options.c:52 configuration_output_handler():
Debug: 5 30 options.c:233 add_default_dirs(): bindir=bin
Debug: 6 34 options.c:234 add_default_dirs(): pkgdatadir=
Debug: 7 38 options.c:235 add_default_dirs(): exepath=D:/apps/xpack-openocd-0.11.0-5/bin
Debug: 8 46 options.c:236 add_default_dirs(): bin2data=../
Debug: 9 50 configuration.c:33 add_script_search_dir(): adding C:/Users/sherm/AppData/Roaming/OpenOCD
Debug: 10 59 configuration.c:33 add_script_search_dir(): adding D:/apps/xpack-openocd-0.11.0-5/bin/..//site
Debug: 11 67 configuration.c:33 add_script_search_dir(): adding D:/apps/xpack-openocd-0.11.0-5/bin/..//scripts
Debug: 12 77 command.c:155 script_debug(): command - ocd_find interface/ftdi/olimex-arm-usb-tiny-h.cfg
Debug: 13 85 configuration.c:88 find_file(): found D:/apps/xpack-openocd-0.11.0-5/bin/..//scripts/interface/ftdi/olimex-arm-usb-tiny-h.cfg
Debug: 14 101 command.c:155 script_debug(): command - adapter driver ftdi
Debug: 15 108 command.c:155 script_debug(): command - ftdi device_desc Olimex OpenOCD JTAG ARM-USB-TINY-H
Debug: 16 116 command.c:155 script_debug(): command - ftdi vid_pid 0x15ba 0x002a
Debug: 17 123 command.c:155 script_debug(): command - ftdi layout_init 0x0808 0x0a1b
Debug: 18 129 command.c:155 script_debug(): command - ftdi layout_signal nSRST -oe 0x0200
Debug: 19 137 command.c:155 script_debug(): command - ftdi layout_signal nTRST -data 0x0100 -oe 0x0100
Debug: 20 144 command.c:155 script_debug(): command - ftdi layout_signal LED -data 0x0800
Debug: 21 152 command.c:155 script_debug(): command - ocd_find fe310.cfg
Debug: 22 160 configuration.c:88 find_file(): found fe310.cfg
Debug: 23 166 command.c:155 script_debug(): command - adapter speed 2500
Debug: 24 171 adapter.c:251 adapter_config_khz(): handle adapter khz
Debug: 25 176 adapter.c:215 adapter_khz_to_speed(): convert khz to adapter specific speed value
Debug: 26 184 adapter.c:215 adapter_khz_to_speed(): convert khz to adapter specific speed value
Debug: 27 195 command.c:155 script_debug(): command - gdb_port disabled
Debug: 28 205 command.c:155 script_debug(): command - tcl_port disabled
Debug: 29 212 command.c:155 script_debug(): command - telnet_port disabled
Debug: 30 224 command.c:155 script_debug(): command - transport select jtag
Debug: 31 234 command.c:155 script_debug(): command - jtag newtap riscv cpu -irlen 5 -expected-id 0x20000913 -ignore-version -ignore-bypass
Debug: 32 250 tcl.c:557 jim_newtap_cmd(): Creating New Tap, Chip: riscv, Tap: cpu, Dotted: riscv.cpu, 6 params
Debug: 33 265 tcl.c:582 jim_newtap_cmd(): Processing option: -irlen
Debug: 34 271 tcl.c:582 jim_newtap_cmd(): Processing option: -expected-id
Debug: 35 282 tcl.c:582 jim_newtap_cmd(): Processing option: -ignore-version
Debug: 36 289 tcl.c:582 jim_newtap_cmd(): Processing option: -ignore-bypass
Debug: 37 299 core.c:1474 jtag_tap_init(): Created Tap: riscv.cpu @ abs position 0, irlen 5, capture: 0x1 mask: 0x3
Debug: 38 313 command.c:155 script_debug(): command - target create riscv.cpu.0 riscv -chain-position riscv.cpu -coreid 0
Debug: 39 331 target.c:2199 target_free_all_working_areas_restore(): freeing all working areas
Debug: 40 343 riscv.c:427 riscv_create_target(): riscv_create_target()
Debug: 41 353 command.c:155 script_debug(): command - riscv.cpu.0 configure -work-area-phys 0x80000000 -work-area-size 0x10000 -work-area-backup 0
Debug: 42 375 target.c:2199 target_free_all_working_areas_restore(): freeing all working areas
Debug: 43 383 target.c:2199 target_free_all_working_areas_restore(): freeing all working areas
Debug: 44 396 target.c:2199 target_free_all_working_areas_restore(): freeing all working areas
Debug: 45 407 command.c:155 script_debug(): command - adapter speed 500
Debug: 46 421 adapter.c:251 adapter_config_khz(): handle adapter khz
Debug: 47 428 adapter.c:215 adapter_khz_to_speed(): convert khz to adapter specific speed value
Debug: 48 440 adapter.c:215 adapter_khz_to_speed(): convert khz to adapter specific speed value
Debug: 49 455 command.c:155 script_debug(): command - reset_config none
Debug: 50 466 command.c:155 script_debug(): command - init
Debug: 51 471 command.c:155 script_debug(): command - target init
Debug: 52 477 command.c:155 script_debug(): command - target names
Debug: 53 487 command.c:155 script_debug(): command - riscv.cpu.0 cget -event gdb-flash-erase-start
Debug: 54 499 command.c:155 script_debug(): command - riscv.cpu.0 configure -event gdb-flash-erase-start reset init
Debug: 55 512 command.c:155 script_debug(): command - riscv.cpu.0 cget -event gdb-flash-write-end
Debug: 56 521 command.c:155 script_debug(): command - riscv.cpu.0 configure -event gdb-flash-write-end reset halt
Debug: 57 534 command.c:155 script_debug(): command - riscv.cpu.0 cget -event gdb-attach
Debug: 58 545 command.c:155 script_debug(): command - riscv.cpu.0 configure -event gdb-attach halt 1000
Debug: 59 554 target.c:1657 handle_target_init_command(): Initializing targets...
Debug: 60 566 riscv.c:440 riscv_init_target(): riscv_init_target()
Debug: 61 575 semihosting_common.c:109 semihosting_common_init():
Debug: 62 586 ftdi.c:654 ftdi_initialize(): ftdi interface using shortest path jtag state transitions
Debug: 63 680 mpsse.c:412 mpsse_purge(): -
Debug: 64 684 mpsse.c:693 mpsse_loopback_config(): off
Debug: 65 689 mpsse.c:738 mpsse_set_frequency(): target 500000 Hz
Debug: 66 696 mpsse.c:730 mpsse_rtck_config(): off
Debug: 67 705 mpsse.c:719 mpsse_divide_by_5_config(): off
Debug: 68 711 mpsse.c:699 mpsse_set_divisor(): 59
Debug: 69 720 mpsse.c:762 mpsse_set_frequency(): actually 500000 Hz
Debug: 70 727 adapter.c:215 adapter_khz_to_speed(): convert khz to adapter specific speed value
Debug: 71 739 adapter.c:219 adapter_khz_to_speed(): have adapter set up
Debug: 72 754 mpsse.c:738 mpsse_set_frequency(): target 500000 Hz
Debug: 73 764 mpsse.c:730 mpsse_rtck_config(): off
Debug: 74 769 mpsse.c:719 mpsse_divide_by_5_config(): off
Debug: 75 779 mpsse.c:699 mpsse_set_divisor(): 59
Debug: 76 784 mpsse.c:762 mpsse_set_frequency(): actually 500000 Hz
Debug: 77 796 adapter.c:215 adapter_khz_to_speed(): convert khz to adapter specific speed value
Debug: 78 803 adapter.c:219 adapter_khz_to_speed(): have adapter set up
Info : 79 814 adapter.c:179 adapter_init(): clock speed 500 kHz
Debug: 80 819 openocd.c:150 handle_init_command(): Debug Adapter init complete
Debug: 81 831 command.c:155 script_debug(): command - transport init
Debug: 82 841 transport.c:219 handle_transport_init(): handle_transport_init
Debug: 83 856 core.c:830 jtag_add_reset(): SRST line released
Debug: 84 867 core.c:855 jtag_add_reset(): TRST line released
Debug: 85 878 core.c:328 jtag_call_event_callbacks(): jtag event: TAP reset
Debug: 86 888 command.c:155 script_debug(): command - jtag arp_init
Debug: 87 895 core.c:1509 jtag_init_inner(): Init JTAG chain
Debug: 88 905 core.c:328 jtag_call_event_callbacks(): jtag event: TAP reset
Debug: 89 913 core.c:1234 jtag_examine_chain(): DR scan interrogation for IDCODE/BYPASS
Debug: 90 923 core.c:328 jtag_call_event_callbacks(): jtag event: TAP reset
Info : 91 939 core.c:1133 jtag_examine_chain_display(): JTAG tap: riscv.cpu tap/device found: 0x20000913 (mfg: 0x489 (SiFive Inc), part: 0x0000, ver: 0x2)
Debug: 92 956 core.c:1364 jtag_validate_ircapture(): IR capture validation scan
Debug: 93 970 core.c:1421 jtag_validate_ircapture(): riscv.cpu: IR capture 0x01
Debug: 94 982 command.c:155 script_debug(): command - dap init
Debug: 95 988 arm_dap.c:97 dap_init_all(): Initializing all DAPs ...
Debug: 96 999 openocd.c:167 handle_init_command(): Examining targets...
Debug: 97 1006 target.c:1843 target_call_event_callbacks(): target event 19 (examine-start) for core riscv.cpu.0
Debug: 98 1019 riscv.c:1120 riscv_examine(): riscv_examine()
Debug: 99 1029 riscv.c:401 dtmcontrol_scan(): DTMCONTROL: 0x0 -> 0x5071
Debug: 100 1036 riscv.c:1130 riscv_examine(): dtmcontrol=0x5071
Debug: 101 1046 riscv.c:1132 riscv_examine():   version=0x1
Debug: 102 1052 riscv-013.c:2281 init_target(): init
Debug: 103 1064 riscv-013.c:451 dtmcontrol_scan(): DTMCS: 0x0 -> 0x5071
Debug: 104 1070 riscv-013.c:1571 examine(): dtmcontrol=0x5071
Debug: 105 1081 riscv-013.c:1572 examine():   dmireset=0
Debug: 106 1086 riscv-013.c:1573 examine():   idle=5
Debug: 107 1096 riscv-013.c:1574 examine():   dmistat=0
Debug: 108 1101 riscv-013.c:1575 examine():   abits=7
Debug: 109 1110 riscv-013.c:1576 examine():   version=1
Debug: 110 1121 riscv-013.c:257 get_dm(): [0] Allocating new DM
Debug: 111 1129 riscv-013.c:397 scan(): 41b w 00000000 @10 -> + 00000000 @00; 0i
Debug: 112 1141 riscv-013.c:397 scan(): 41b - 00000000 @10 -> + 03ff0001 @10; 0i
Debug: 113 1155 riscv-013.c:407 scan():  ->  hartsello=1023 dmactive
Debug: 114 1162 riscv-013.c:397 scan(): 41b w 00000001 @10 -> + 00000000 @00; 0i
Debug: 115 1174 riscv-013.c:407 scan():  dmactive ->
Debug: 116 1187 riscv-013.c:397 scan(): 41b - 00000000 @10 -> + 00000000 @10; 0i
Debug: 117 1196 riscv-013.c:397 scan(): 41b w 07ffffc1 @10 -> + 00000000 @00; 0i
Debug: 118 1206 riscv-013.c:407 scan():  hasel hartselhi=1023 hartsello=1023 dmactive ->
Debug: 119 1223 riscv-013.c:397 scan(): 41b - 00000000 @10 -> + 00000001 @10; 0i
Debug: 120 1238 riscv-013.c:407 scan():  ->  dmactive
Debug: 121 1249 riscv-013.c:397 scan(): 41b r 00000000 @10 -> + 00000000 @00; 0i
Debug: 122 1256 riscv-013.c:397 scan(): 41b - 00000000 @10 -> + 03ff0001 @10; 0i
Debug: 123 1267 riscv-013.c:407 scan():  ->  hartsello=1023 dmactive
Debug: 124 1274 riscv-013.c:397 scan(): 41b r 00000000 @11 -> + 00000000 @00; 0i
Debug: 125 1286 riscv-013.c:397 scan(): 41b - 00000000 @11 -> b 00000000 @00; 0i
Debug: 126 1297 riscv-013.c:460 increase_dmi_busy_delay(): dtmcs_idle=5, dmi_busy_delay=1, ac_busy_delay=0

infinite loop with these three lines ...
Debug: 127 1312 riscv-013.c:451 dtmcontrol_scan(): DTMCS: 0x10000 -> 0x5471
Debug: 128 1320 riscv-013.c:397 scan(): 41b - 00000000 @11 -> b 00000000 @00; 1i
Debug: 129 1332 riscv-013.c:460 increase_dmi_busy_delay(): dtmcs_idle=5, dmi_busy_delay=2, ac_busy_delay=0
... to here

Debug: 364 4162 riscv-013.c:451 dtmcontrol_scan(): DTMCS: 0x10000 -> 0x5471
Debug: 365 4171 target.c:1843 target_call_event_callbacks(): target event 20 (examine-fail) for core riscv.cpu.0
Warn : 366 4185 target.c:802 target_examine(): target riscv.cpu.0 examination failed
Debug: 367 4193 openocd.c:169 handle_init_command(): target examination failed
Debug: 368 4204 command.c:155 script_debug(): command - flash init
Debug: 369 4210 tcl.c:1375 handle_flash_init_command(): Initializing flash devices...
Debug: 370 4222 command.c:155 script_debug(): command - nand init
Debug: 371 4237 tcl.c:487 handle_nand_init_command(): Initializing NAND devices...
Debug: 372 4248 command.c:155 script_debug(): command - pld init
Debug: 373 4254 pld.c:194 handle_pld_init_command(): Initializing PLDs...
Debug: 374 4264 command.c:155 script_debug(): command - tpiu init
Info : 375 4270 gdb_server.c:3832 gdb_target_add_one(): gdb port disabled
Debug: 376 4280 command.c:155 script_debug(): command - shutdown
User : 377 4287 server.c:753 handle_shutdown_command(): shutdown command invoked
Debug: 378 4298 riscv.c:489 riscv_deinit_target(): riscv_deinit_target()
Debug: 379 4304 riscv-013.c:1526 deinit_target(): riscv_deinit_target()
Debug: 380 4315 target.c:2199 target_free_all_working_areas_restore(): freeing all working areas

Doesn’t dmi_busy_delay go up, and correspondingly the number before i on e.g. line 128?

In any case, the target is reporting DMI is busy after a read request. OpenOCD then keeps scanning waiting for the DMI busy bit to go low, but it doesn’t go low. The first read to the DM on line 121 looks normal, so there’s definitely some communication working over the DMI. I’d try to get more information about what is going on between DTM and DM.