Incorrect "valid" read of `menvcfg` CSR from HiFive1 board

[TommyMurphyTM1234]

Split out from this issue:

• https://github.com/riscv-collab/riscv-openocd/issues/1047#issuecomment-2074197697

I'm using this build of OpenOCD:

• https://github.com/riscv-collab/riscv-openocd/issues/1047#issuecomment-2072335919

TOT (top of tree) RISC-V OpenOCD + https://github.com/riscv-collab/riscv-openocd/pull/1046 + https://github.com/riscv-collab/riscv-openocd/pull/1054)

openocd -v
Open On-Chip Debugger 0.12.0+dev-03744-g3991492cc-dirty (2024-04-23-15:11)
Licensed under GNU GPL v2
For bug reports, read
http://openocd.org/doc/doxygen/bugs.html

When I run the DisconnectTest test I get this:

./gdbserver.py targets/SiFive/HiFive1.py DisconnectTest --server_cmd "openocd -d3"
PRNG seed for HiFive1 is generated automatically
PRNG seed for HiFive1 is 1713948851
Using $misa from hart definition: 0x40001105
[DisconnectTest] Starting > logs/20240424-095411-HiFive1-DisconnectTest.log
[DisconnectTest] fail in 13.72s
::::::::::::::::::::::::::::[ ran 1 tests in 14s ]::::::::::::::::::::::::::::
1 tests returned fail
DisconnectTest > logs/20240424-095411-HiFive1-DisconnectTest.log

This is the resulting log:

• logs/20240424-095411-HiFive1-DisconnectTest.log: 20240424-095411-HiFive1-DisconnectTest.log

This test reads all registers, disconnects/reconnects, reads all registers again and compares the two sets of values. The test passes if they match and fails if they don't.

In this case it fails because the first read of menvcfg correctly fails because it is not implemented on this M-mode only target (SiFive HiFive1 Rev A01 using the FE310-G000 CPU). But the second read after the disconnect "succeeds" but seems to get the value of mtvec:

# First read
...
mtvec          0x204000b4       541065396
menvcfg        Could not fetch register "menvcfg"; remote failure reply 'E0E'
...

# Second read
...
mtvec          0x204000b4       541065396
menvcfg        0x204000b4       541065396
...

I think that these are the relevant snippets of the OpenOCD verbose log:

# First read
...
Debug: 3631 2182 riscv.c:5258 riscv_get_register(): [riscv.cpu] Reading menvcfg from target
Debug: 3632 2182 riscv-011.c:772 cache_set32(): cache[0x0] = 0x30a02473: csrr    s0, menvcfg
Debug: 3633 2182 riscv-011.c:769 cache_set32(): cache[0x1] = 0x40802823: sw      s0, 1040(zero) (hit)
Debug: 3634 2182 riscv-011.c:769 cache_set32(): cache[0x2] = 0x3fc0006f: j       pc + 0x3fc (hit)
Debug: 3635 2182 riscv-011.c:861 cache_write(): enter
Debug: 3636 2184 riscv-011.c:408 scan(): 41b w ih:30a02473 @00 -> + .h:30502473 @00
Debug: 3637 2184 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + .h:30502473 @00
Debug: 3638 2184 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + .h:204000b4 @04
Debug: 3639 2184 riscv-011.c:983 cache_write(): exit
Debug: 3640 2188 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:204000b4 @04
Debug: 3641 2192 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:ffffffff @06
Warn : 3642 2192 riscv-011.c:1250 register_read(): Got exception 0xffffffff when reading menvcfg
Debug: 3643 2192 gdb_server.c:1539 gdb_error(): Reporting 0 to GDB as generic error
Debug: 3644 2192 gdb_server.c:441 gdb_log_outgoing_packet(): [riscv.cpu] {1} sending packet: $E0E#ba
...

# Second read
...
Debug: 9958 6693 riscv.c:5258 riscv_get_register(): [riscv.cpu] Reading menvcfg from target
Debug: 9959 6693 riscv-011.c:772 cache_set32(): cache[0x0] = 0x30a02473: csrr    s0, menvcfg
Debug: 9960 6693 riscv-011.c:769 cache_set32(): cache[0x1] = 0x40802823: sw      s0, 1040(zero) (hit)
Debug: 9961 6693 riscv-011.c:769 cache_set32(): cache[0x2] = 0x3fc0006f: j       pc + 0x3fc (hit)
Debug: 9962 6693 riscv-011.c:861 cache_write(): enter
Debug: 9963 6696 riscv-011.c:408 scan(): 41b w ih:30a02473 @00 -> + .h:00000000 @06
Debug: 9964 6696 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> b ..:00000000 @00
Debug: 9965 6696 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> b ..:00000000 @00
Debug: 9966 6696 riscv-011.c:337 increase_dbus_busy_delay(): dtmcontrol_idle=5, dbus_busy_delay=1, interrupt_high_delay=0
Debug: 9967 6701 riscv-011.c:299 dtmcontrol_scan(): DTMCONTROL: 0x10000 -> 0x1550
Debug: 9968 6704 riscv-011.c:408 scan(): 41b w ih:30a02473 @00 -> + .h:30502473 @00
Debug: 9969 6706 riscv-011.c:408 scan(): 41b w .h:40802823 @01 -> + .h:30a02473 @00
Debug: 9970 6711 riscv-011.c:408 scan(): 41b w .h:3fc0006f @02 -> + .h:40802823 @01
Debug: 9971 6712 riscv-011.c:408 scan(): 41b w .h:3f80006f @03 -> + .h:3fc0006f @02
Debug: 9972 6714 riscv-011.c:408 scan(): 41b w .h:204000b4 @04 -> + .h:3f80006f @03
Debug: 9973 6718 riscv-011.c:408 scan(): 41b w .h:80000370 @05 -> + .h:204000b4 @04
Debug: 9974 6721 riscv-011.c:408 scan(): 41b w .h:00000000 @06 -> + .h:80000370 @05
Debug: 9975 6722 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + .h:ffffffff @06
Debug: 9976 6724 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + .h:30a02473 @00
Debug: 9977 6724 riscv-011.c:983 cache_write(): exit
Debug: 9978 6729 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:30a02473 @00
Debug: 9979 6730 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:00000000 @06
Debug: 9980 6734 riscv-011.c:408 scan(): 41b r ..:00000000 @04 -> + .h:00000000 @06
Debug: 9981 6736 riscv-011.c:408 scan(): 41b r ..:00000000 @04 -> + .h:204000b4 @04
Debug: 9982 6736 riscv-011.c:1256 register_read(): reg[843]=0x204000b4
Debug: 9983 6736 riscv.c:5267 riscv_get_register(): [riscv.cpu] Read menvcfg: 0x204000b4
Debug: 9984 6736 riscv.c:5722 register_get(): [riscv.cpu] Read 0x204000b4 from menvcfg (valid=0).
Debug: 9985 6736 gdb_server.c:441 gdb_log_outgoing_packet(): [riscv.cpu] {2} sending packet: $b4004020#bc
...

Is there a bug in the caching of registers that causes this?

[TommyMurphyTM1234]

While I can reproduce this reliably by running the DisconnectTest test via the test suite, so far I have not been able to reproduce it by exercising the test manually by running OpenOCD/GDB standalone and feeding GDB the relevant commands interactively. I also tried changing the DisconnectTest test to only read the menvcfg CSR and not all registers but in that case the problem does not arise so it may be somehow linked to the bulk read of all registers in one go.

[TommyMurphyTM1234]

Is this triggering something that causes the wrong value to be read?

Debug: 9966 6696 riscv-011.c:337 increase_dbus_busy_delay(): dtmcontrol_idle=5, dbus_busy_delay=1, interrupt_high_delay=0
Debug: 9967 6701 riscv-011.c:299 dtmcontrol_scan(): DTMCONTROL: 0x10000 -> 0x1550

[TommyMurphyTM1234]

@en-sc - maybe when you get a chance you could look at this as you probably know a lot more about the mechanics of the caching that's going on here than I do (which wouldn't be difficult! 🤣 ).

[en-sc]

@TommyMurphyTM1234, thanks for the great analysis!

Disclaimer: I have not read RISC-V Debug Spec v0.11 nor developed the related code. So this analysis is more of a guess than a definitive truth.

AFAIU, the issue is internal to riscv-011.c and is not connected to register caching.

Taking a look at the snippets you've provided one can see:

• First read:

  1. Filling a local cache with a program to execute (no transfers to target, just preparing a bunch of operations to add to JTAG queue):

     Debug: 3632 2182 riscv-011.c:772 cache_set32(): cache[0x0] = 0x30a02473: csrr    s0, menvcfg
     Debug: 3633 2182 riscv-011.c:769 cache_set32(): cache[0x1] = 0x40802823: sw      s0, 1040(zero) (hit)
     Debug: 3634 2182 riscv-011.c:769 cache_set32(): cache[0x2] = 0x3fc0006f: j       pc + 0x3fc (hit)

  2. Starting the transfer. ih indicates DMCONTROL_INTERRUPT, which, AFAIU, starts the execution of the program in DRAM.

     Debug: 3635 2182 riscv-011.c:861 cache_write(): enter
     Debug: 3636 2184 riscv-011.c:408 scan(): 41b w ih:30a02473 @00 -> + .h:30502473 @00

  3. Then there are two reads, the first returns garbage (https://github.com/riscv-collab/riscv-openocd/blob/riscv/src/target/riscv/riscv-011.c#L888-L889) and the second returns a value containing the interrupt bit (AFAIU, this is analogous to abstractcs.busy).

     Debug: 3637 2184 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + .h:30502473 @00
     Debug: 3638 2184 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + .h:204000b4 @04
     Debug: 3639 2184 riscv-011.c:983 cache_write(): exit

  4. Now the program is executed and it's time to retrieve results

     Debug: 3639 2184 riscv-011.c:983 cache_write(): exit
     Debug: 3640 2188 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:204000b4 @04
     Debug: 3641 2192 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:ffffffff @06

  5. And it's an exception, as indicated by -> + .h:ffffffff @06

     Warn : 3642 2192 riscv-011.c:1250 register_read(): Got exception 0xffffffff when reading menvcfg

• Second read:

1. The same
2. The same
3. The reads indicate return busy. So the delays are increased.

   Debug: 9964 6696 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> b ..:00000000 @00
   Debug: 9965 6696 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> b ..:00000000 @00
   Debug: 9966 6696 riscv-011.c:337 increase_dbus_busy_delay(): dtmcontrol_idle=5, dbus_busy_delay=1, interrupt_high_delay=0
   Debug: 9967 6701 riscv-011.c:299 dtmcontrol_scan(): DTMCONTROL: 0x10000 -> 0x1550

4. And the whole process is started again. Cache is disregarded, so all writes are executed. Moreover, AFAIU, the return values are placed at the some location in this DRAM, so, to be safe, dram cache is flushed completely (https://github.com/riscv-collab/riscv-openocd/blob/riscv/src/target/riscv/riscv-011.c#L929):

   Debug: 9968 6704 riscv-011.c:408 scan(): 41b w ih:30a02473 @00 -> + .h:30502473 @00
   Debug: 9969 6706 riscv-011.c:408 scan(): 41b w .h:40802823 @01 -> + .h:30a02473 @00
   Debug: 9970 6711 riscv-011.c:408 scan(): 41b w .h:3fc0006f @02 -> + .h:40802823 @01
   Debug: 9971 6712 riscv-011.c:408 scan(): 41b w .h:3f80006f @03 -> + .h:3fc0006f @02
   Debug: 9972 6714 riscv-011.c:408 scan(): 41b w .h:204000b4 @04 -> + .h:3f80006f @03
   Debug: 9973 6718 riscv-011.c:408 scan(): 41b w .h:80000370 @05 -> + .h:204000b4 @04
   Debug: 9974 6721 riscv-011.c:408 scan(): 41b w .h:00000000 @06 -> + .h:80000370 @05

5. Now wait for execution to end (https://github.com/riscv-collab/riscv-openocd/blob/riscv/src/target/riscv/riscv-011.c#L940). Here the exception gets returned -> + .h:ffffffff @06, but it is discarded (https://github.com/riscv-collab/riscv-openocd/blob/riscv/src/target/riscv/riscv-011.c#L726-L730). I think this is the issue. I'm not sure how to fix this, since I'm not that familiar with 0.11 spec.

   Debug: 9975 6722 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + .h:ffffffff @06
   Debug: 9976 6724 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + .h:30a02473 @00
   Debug: 9977 6724 riscv-011.c:983 cache_write(): exit

6. Now there is no error (step 5 discarded it) and we read both the error and the value.

   Debug: 9978 6729 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:30a02473 @00
   Debug: 9979 6730 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:00000000 @06
   Debug: 9980 6734 riscv-011.c:408 scan(): 41b r ..:00000000 @04 -> + .h:00000000 @06
   Debug: 9981 6736 riscv-011.c:408 scan(): 41b r ..:00000000 @04 -> + .h:204000b4 @04
   Debug: 9982 6736 riscv-011.c:1256 register_read(): reg[843]=0x204000b4

TLDR

I think the issue is RISC-V 0.11 specific and one would need to be quite knowledgeable in RISC-V Debug v0.11 to fix it (I'm not). Fixing the issue may take some time.

On a side note, @TommyMurphyTM1234, does the test fails always on menvcfg or sometimes the value of another register differs? If so, this would somewhat confirm my theory.

[TommyMurphyTM1234]

Thanks a lot for the detailed analysis @en-sc.

Just to address this specific point:

On a side note, @TommyMurphyTM1234, does the test fails always on menvcfg or sometimes the value of another register differs? If so, this would somewhat confirm my theory.

The test fails every time (not sporadically) and always in the same way - i.e. a mismatch between the old and new (after disconnect/reconnect) values of menvcfg.

[TommyMurphyTM1234]

It probably doesn't add anything to the analysis but if I reduce the JTAG clock speed from 10Mhz to, say, 5MHz:

• https://github.com/riscv-software-src/riscv-tests/blob/6b1d7372d951ed75811e0a09c0fe9e065c141c2d/debug/targets/SiFive/HiFive1.cfg#L1

then the problem goes away but only because the DBUS delay "backoff" increments and register read retries disappear.

But I presume that the issue with the incorrect successful read of menvcfg after such a backoff delay is the real problem. Still no idea why it only seems to happen for that specific register though... 😕

[TommyMurphyTM1234]

I bumped the clock speed up to 30MHz just to see if I could trigger the problem with another CSR but without success.

However I noticed a few things.

The first read of menvcfg never involves any DBUS delay "backoffs" no matter what the clock speed:

Debug: 5313 1998 gdb_server.c:424 gdb_log_incoming_packet(): [riscv.cpu] {1} received packet: p34b
Debug: 5314 1998 riscv.c:2672 riscv_get_gdb_reg_list_internal(): [riscv.cpu] reg_class=0, read=0
Debug: 5315 1998 riscv.c:5258 riscv_get_register(): [riscv.cpu] Reading menvcfg from target
Debug: 5316 1999 riscv-011.c:772 cache_set32(): cache[0x0] = 0x30a02473: csrr    s0, menvcfg
Debug: 5317 1999 riscv-011.c:769 cache_set32(): cache[0x1] = 0x40802823: sw      s0, 1040(zero) (hit)
Debug: 5318 1999 riscv-011.c:769 cache_set32(): cache[0x2] = 0x3fc0006f: j       pc + 0x3fc (hit)
Debug: 5319 1999 riscv-011.c:861 cache_write(): enter
Debug: 5320 2001 riscv-011.c:408 scan(): 41b w ih:30a02473 @00 -> + .h:00000000 @06
Debug: 5321 2001 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + .h:30502473 @00
Debug: 5322 2001 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + .h:204000b4 @04
Debug: 5323 2001 riscv-011.c:983 cache_write(): exit
Debug: 5324 2002 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:204000b4 @04
Debug: 5325 2004 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:ffffffff @06
Warn : 5326 2004 riscv-011.c:1250 register_read(): Got exception 0xffffffff when reading menvcfg
Debug: 5327 2004 gdb_server.c:1539 gdb_error(): Reporting 0 to GDB as generic error
Debug: 5328 2004 gdb_server.c:441 gdb_log_outgoing_packet(): [riscv.cpu] {1} sending packet: $E0E#ba

The second one always does and results in the incorrect "successful" read:

Debug: 11791 7104 gdb_server.c:424 gdb_log_incoming_packet(): [riscv.cpu] {2} received packet: p34b
Debug: 11792 7104 riscv.c:2672 riscv_get_gdb_reg_list_internal(): [riscv.cpu] reg_class=0, read=0
Debug: 11793 7104 riscv.c:5258 riscv_get_register(): [riscv.cpu] Reading menvcfg from target
Debug: 11794 7104 riscv-011.c:772 cache_set32(): cache[0x0] = 0x30a02473: csrr    s0, menvcfg
Debug: 11795 7104 riscv-011.c:769 cache_set32(): cache[0x1] = 0x40802823: sw      s0, 1040(zero) (hit)
Debug: 11796 7104 riscv-011.c:769 cache_set32(): cache[0x2] = 0x3fc0006f: j       pc + 0x3fc (hit)
Debug: 11797 7104 riscv-011.c:861 cache_write(): enter
Debug: 11798 7105 riscv-011.c:408 scan(): 41b w ih:30a02473 @00 -> + .h:00000000 @06
Debug: 11799 7105 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> b ..:00000000 @00
Debug: 11800 7105 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> b ..:00000000 @00
Debug: 11801 7105 riscv-011.c:337 increase_dbus_busy_delay(): dtmcontrol_idle=5, dbus_busy_delay=1, interrupt_high_delay=0
Debug: 11802 7109 riscv-011.c:299 dtmcontrol_scan(): DTMCONTROL: 0x10000 -> 0x1550
Debug: 11803 7111 riscv-011.c:408 scan(): 41b w ih:30a02473 @00 -> + .h:30502473 @00
Debug: 11804 7113 riscv-011.c:408 scan(): 41b w .h:40802823 @01 -> b ..:00000000 @00
Debug: 11805 7113 riscv-011.c:337 increase_dbus_busy_delay(): dtmcontrol_idle=5, dbus_busy_delay=2, interrupt_high_delay=0
Debug: 11806 7121 riscv-011.c:299 dtmcontrol_scan(): DTMCONTROL: 0x10000 -> 0x1550
Debug: 11807 7134 riscv-011.c:408 scan(): 41b w .h:40802823 @01 -> + .h:30a02473 @00
Debug: 11808 7136 riscv-011.c:408 scan(): 41b w .h:3fc0006f @02 -> b ..:00000000 @00
Debug: 11809 7136 riscv-011.c:337 increase_dbus_busy_delay(): dtmcontrol_idle=5, dbus_busy_delay=3, interrupt_high_delay=0
Debug: 11810 7138 riscv-011.c:299 dtmcontrol_scan(): DTMCONTROL: 0x10000 -> 0x1550
Debug: 11811 7142 riscv-011.c:408 scan(): 41b w .h:3fc0006f @02 -> + .h:40802823 @01
Debug: 11812 7144 riscv-011.c:408 scan(): 41b w .h:3f80006f @03 -> b ..:00000000 @00
Debug: 11813 7144 riscv-011.c:337 increase_dbus_busy_delay(): dtmcontrol_idle=5, dbus_busy_delay=4, interrupt_high_delay=0
Debug: 11814 7146 riscv-011.c:299 dtmcontrol_scan(): DTMCONTROL: 0x10000 -> 0x1550
Debug: 11815 7150 riscv-011.c:408 scan(): 41b w .h:3f80006f @03 -> + .h:3fc0006f @02
Debug: 11816 7154 riscv-011.c:408 scan(): 41b w .h:204000b4 @04 -> + .h:3f80006f @03
Debug: 11817 7156 riscv-011.c:408 scan(): 41b w .h:80000370 @05 -> + .h:204000b4 @04
Debug: 11818 7158 riscv-011.c:408 scan(): 41b w .h:00000000 @06 -> + .h:80000370 @05
Debug: 11819 7160 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + .h:ffffffff @06
Debug: 11820 7163 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + .h:30a02473 @00
Debug: 11821 7164 riscv-011.c:983 cache_write(): exit
Debug: 11822 7166 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:30a02473 @00
Debug: 11823 7167 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:00000000 @06
Debug: 11824 7169 riscv-011.c:408 scan(): 41b r ..:00000000 @04 -> + .h:00000000 @06
Debug: 11825 7171 riscv-011.c:408 scan(): 41b r ..:00000000 @04 -> + .h:204000b4 @04
Debug: 11826 7171 riscv-011.c:1256 register_read(): reg[843]=0x204000b4
Debug: 11827 7172 riscv.c:5267 riscv_get_register(): [riscv.cpu] Read menvcfg: 0x204000b4
Debug: 11828 7172 riscv.c:5722 register_get(): [riscv.cpu] Read 0x204000b4 from menvcfg (valid=0).
Debug: 11829 7172 gdb_server.c:441 gdb_log_outgoing_packet(): [riscv.cpu] {2} sending packet: $b4004020#bc

The second read of other CSRs also leads to DBUS "backoff" delays but not the incorrect "successful" read of a value for the register:

Debug: 11831 7175 gdb_server.c:424 gdb_log_incoming_packet(): [riscv.cpu] {2} received packet: p34d
Debug: 11832 7175 riscv.c:2672 riscv_get_gdb_reg_list_internal(): [riscv.cpu] reg_class=0, read=0
Debug: 11833 7175 riscv.c:5258 riscv_get_register(): [riscv.cpu] Reading mstateen0 from target
Debug: 11834 7175 riscv-011.c:772 cache_set32(): cache[0x0] = 0x30c02473: csrr    s0, mstateen0
Debug: 11835 7175 riscv-011.c:769 cache_set32(): cache[0x1] = 0x40802823: sw      s0, 1040(zero) (hit)
Debug: 11836 7175 riscv-011.c:769 cache_set32(): cache[0x2] = 0x3fc0006f: j       pc + 0x3fc (hit)
Debug: 11837 7175 riscv-011.c:861 cache_write(): enter
Debug: 11838 7179 riscv-011.c:408 scan(): 41b w ih:30c02473 @00 -> + .h:30a02473 @00
Debug: 11839 7179 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + .h:30a02473 @00
Debug: 11840 7179 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + ih:204000b4 @04
Debug: 11841 7179 riscv-011.c:348 increase_interrupt_high_delay(): dtmcontrol_idle=5, dbus_busy_delay=4, interrupt_high_delay=1
Debug: 11842 7182 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + ih:204000b4 @04
Debug: 11843 7186 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + .h:30c02473 @00
Debug: 11844 7186 riscv-011.c:983 cache_write(): exit
Debug: 11845 7190 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:30c02473 @00
Debug: 11846 7192 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:ffffffff @06
Warn : 11847 7192 riscv-011.c:1250 register_read(): Got exception 0xffffffff when reading mstateen0
Debug: 11848 7192 gdb_server.c:1539 gdb_error(): Reporting 0 to GDB as generic error
Debug: 11849 7192 gdb_server.c:441 gdb_log_outgoing_packet(): [riscv.cpu] {2} sending packet: $E0E#ba

and

Debug: 11850 7193 gdb_server.c:424 gdb_log_incoming_packet(): [riscv.cpu] {2} received packet: p34e
Debug: 11851 7193 riscv.c:2672 riscv_get_gdb_reg_list_internal(): [riscv.cpu] reg_class=0, read=0
Debug: 11852 7193 riscv.c:5258 riscv_get_register(): [riscv.cpu] Reading mstateen1 from target
Debug: 11853 7193 riscv-011.c:772 cache_set32(): cache[0x0] = 0x30d02473: csrr    s0, mstateen1
Debug: 11854 7193 riscv-011.c:769 cache_set32(): cache[0x1] = 0x40802823: sw      s0, 1040(zero) (hit)
Debug: 11855 7193 riscv-011.c:769 cache_set32(): cache[0x2] = 0x3fc0006f: j       pc + 0x3fc (hit)
Debug: 11856 7193 riscv-011.c:861 cache_write(): enter
Debug: 11857 7197 riscv-011.c:408 scan(): 41b w ih:30d02473 @00 -> + .h:ffffffff @06
Debug: 11858 7197 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + .h:30c02473 @00
Debug: 11859 7197 riscv-011.c:408 scan(): 41b r .h:00000000 @04 -> + ih:204000b4 @04
Debug: 11860 7197 riscv-011.c:348 increase_interrupt_high_delay(): dtmcontrol_idle=5, dbus_busy_delay=4, interrupt_high_delay=2
Debug: 11861 7201 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + ih:204000b4 @04
Debug: 11862 7205 riscv-011.c:408 scan(): 41b r ..:00000000 @00 -> + .h:30d02473 @00
Debug: 11863 7205 riscv-011.c:983 cache_write(): exit
Debug: 11864 7208 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:30d02473 @00
Debug: 11865 7212 riscv-011.c:408 scan(): 41b r ..:00000000 @06 -> + .h:ffffffff @06
Warn : 11866 7213 riscv-011.c:1250 register_read(): Got exception 0xffffffff when reading mstateen1
Debug: 11867 7213 gdb_server.c:1539 gdb_error(): Reporting 0 to GDB as generic error
Debug: 11868 7213 gdb_server.c:441 gdb_log_outgoing_packet(): [riscv.cpu] {2} sending packet: $E0E#ba

So, for some reason, the issue seems (so far) specific to menvcfg and only happens on the second read after DBUS "backoff" delay increments.