[entropy_complex] Debug hang issues

[vogelpi]

Description

While testing #22114 for M3 and investigating a failure of the //sw/device/silicon_creator/manuf/skus/earlgrey_a0/sival_bringup:ft_provision_fpga_cw310_sival test, it was discovered that under certain circumstances, the entropy complex seems to hang (see https://github.com/lowRISC/opentitan/pull/22716#issue-2251855658 for a detailed description).

Changing the reseed rate allowed us to temporarily work around the issue but we need to track down the underlying bug and make sure it's fixed for TO. What we could / should do towards this:

• Locally revert 667b717d38890a04fb2fc29065d4fdd068b23897 and rerun //sw/device/silicon_creator/manuf/skus/earlgrey_a0/sival_bringup:ft_provision_fpga_cw310_sival to make sure the test fails.
• Make use of the debug infrastructure in the entropy complex added by @h-filali for M2 and M3. In particular, the EDNs and CSRNG now properly acknowledge commands and report their status.
• Check if either EDN or CSRNG trigger an internal FIFO error.
• Check the software implementation to see if maybe software doesn't properly wait with pushing commands until the previous command is acknowledged.
• Experiment with different reseed intervals and generate lengths to see if we can trigger the error in a top-level test that can be simulated (to investigate waves).

FYI @timothytrippel @moidx

[timothytrippel]

On the software front, we could created a separate testcase that just contains the parts of the ft_provision test that cause the entropy complex hang up if that would be helpful? I.e., we could create a top-level test that attempts to load an OTBN program (which triggers a secure wipe of the i/d-mems; thus requesting lots of entropy) and then attempt to do a keymgr operation which requests even more entropy. We could make this TLT device-code oonly, then there would be something to run DV.

Though if there is a block level DV test that could already be used to tease out the root problem that may be quicker.

[andreaskurth]

@vogelpi will work on this as soon as M3 is complete. This may be related to an issue reported by @pamaury where in ROM_EXT a huge amount of entropy is requested.

By @moidx: We could set up the same configuration in a DV test. By @vogelpi: We have an existing DV test running; it just takes a long time.

[vsukhoml]

I was trying to dump entropy from entropy_src through uart for analysis. And for the case when I just read 4000000 bits (500000 words) in few long reads, each about 80KB of data - everything works fine. But when I switch to restart test where I read chunks of 1024/4096 bits and print them via UART i start to observe dropped symbols - hex lines becomes ragged and it is very easily reproduced after about 300-500 seconds of work. Is there any reasonable path how disable/enable entropy source (with EDN disabled) can lead to this?

I use test entropy_src_fw_observe_many_continous as a basis and change:

static status_t entropy_config(
    dif_entropy_src_single_bit_mode_t single_bit_mode) {

  // Disable the entropy complex.
  TRY(entropy_testutils_stop_all());
  // Disable all health tests.
  TRY(entropy_testutils_disable_health_tests(&entropy_src));

  // Enable FW override.
  TRY(dif_entropy_src_fw_override_configure(
      &entropy_src,
      (dif_entropy_src_fw_override_config_t){
          .entropy_insert_enable = false,
          .buffer_threshold = kEntropySrcFifoThreshold,
      },
      kDifToggleEnabled));
  // Enable entropy_src.
  TRY(dif_entropy_src_configure(
      &entropy_src,
      (dif_entropy_src_config_t){
          .fips_enable = true,
          .route_to_firmware = false,
          .bypass_conditioner = false,
          .single_bit_mode = single_bit_mode,
          .health_test_threshold_scope = false,
          .health_test_window_size = kEntropySrcHealthTestWindowSize,
          .alert_threshold = UINT16_MAX},
      kDifToggleEnabled));

  return OK_STATUS();
}
...
static void print_uart(const char *buf, size_t len) {
  for (size_t i = 0; i < len; ++i) {
    while (dif_uart_byte_send_polled(uart, buf[i]) != kDifOk)
      ;
  }
  return;
}

// Dump in batches of 1000 samples and then restart
status_t firmware_override_observe_restart(
    int32_t nr_samples, dif_entropy_src_single_bit_mode_t single_bit_mode) {

  const int32_t total_rounds = (nr_samples + 999) / 1000;
  int32_t rounds_to_run = total_rounds;
  const int32_t bits_in_round = 1000 * ((single_bit_mode == kDifEntropySrcSingleBitModeDisabled) ? 4 : 1);
  // Slow computation: do it once.
  const int32_t bits_per_word = CHAR_BIT * sizeof(sample_buffer[0]);
  // We always read 32-bits. TODO: multiply by 4 in 4-bit mode?
  const int32_t words_in_round = (bits_in_round + bits_per_word - 1) / bits_per_word;
  const int32_t bytes_in_round = (bits_in_round + CHAR_BIT - 1) / CHAR_BIT;

  LOG_INFO("==================");
  LOG_INFO("Running restart test in mode %u, retrieve %u words, bytes %u, rounds %u",
           single_bit_mode, words_in_round, bytes_in_round, total_rounds);
  if (words_in_round > kContiguousSamplesCount)
    return INVALID_ARGUMENT();

  // Set timeout to worst case.
  ibex_timeout_t tmo = ibex_timeout_init(6000000);
  // Drain FIFO to make sure we get contiguous samples.
  print_uart("~~~\n", 4);
  uint32_t entropy_full_event = 0;
  uint64_t elapsed = 0;
  bool timeout = false;
  uint32_t uart_counter = 0;
  while (rounds_to_run) {
    // Collect samples from the the observe FIFO.
    int32_t words_to_read = words_in_round;
    uint32_t *sample_buffer_ptr = sample_buffer;

    // Restart the entropy complex.
    entropy_config(single_bit_mode);

    // Collect.
    while (words_to_read > 0 && !(timeout = ibex_timeout_check(&tmo))) {
      size_t len = (size_t)words_to_read;
      uint32_t err_code;
      TRY(dif_entropy_src_get_errors(&entropy_src, &err_code));
      if (err_code)
        LOG_ERROR("entropy_src status. err: 0x%x", err_code);

      // Check FIFO did not overflow during collection.
      entropy_full_event += entropy_src_fifo_has_overflowed();
      TRY(dif_entropy_src_observe_fifo_nonblocking_read(
          &entropy_src, sample_buffer_ptr, &len));
      sample_buffer_ptr += len;
      words_to_read -= len;
    }
    elapsed += ibex_timeout_elapsed(&tmo);
    // Handle partial & timed-out reads
    rounds_to_run--;
    if (timeout)
      break;
    // Print output
    uart_counter = print_hex_uart((uint8_t *)sample_buffer,
                                  (size_t)bytes_in_round, uart_counter);
    // Reset timer for next iteration
    tmo = ibex_timeout_init(6000000);
  }
  print_uart("\n~~~\n", 5);
  TRY_CHECK(!timeout, "Timeout during capture");
  TRY_CHECK(entropy_full_event == 0, "Unexpected stalls at collection %u",
            entropy_full_event);
  // Make sure the FIFO did not overflow.

  uint64_t freq = udiv64_slow(
      ((uint64_t)(total_rounds - rounds_to_run) * (uint64_t)words_in_round) *
          (uint64_t)1000000,
      elapsed, NULL);
  LOG_INFO("done in %ums (~ %usamples/s)",
           (uint32_t)udiv64_slow(elapsed, 1000, NULL), (uint32_t)freq);

  return OK_STATUS();
}

No entropy source errors are reported in the process.

[vogelpi]

I would like to start looking into this issue this week. @timothytrippel , it would be awesome if you could create that separate testcase for simulation. I would then have a perfect basis to start my investigation from (after undoing some recent keymgr and software changes). In parallel, @h-filali is investigating some EDN block-level DV failures which may be related.

[timothytrippel]

@vogelpi : I created a created a branch with the example test: https://github.com/timothytrippel/opentitan/tree/entropy-complex-dbg

You can run it on the CW310 fpga or in DV with the test ROM. I was not able to replicate the failure on the FPGA like I had before, but you mentioned you needed to unwind some HW changes to trigger this most likely? Anywho, the test emulates as closely as possible the entropy complex operations executed by the ft_personalize.c binary. In the process, I also became aware we are probably not being as efficient as possible with the calls, so I plan to clean things up in a follow up PR as well.

Lmk, if you have any questions. Thanks for your help!

[vogelpi]

Thanks again Tim for preparing this test. I've now checked out the repository at 903b31917104b6d9e22f0eb41941a72415109a8a (After merging @h-filali 's PR #22114), then reverted your commit 667b717d38890a04fb2fc29065d4fdd068b23897 (PR 22716, I think the same commit is also part of your referenced dev branch) and then added your commit to get the test application. I've generated the CW310 FPGA bistream and also collected waves using DVSIM. What I've found is the following:

• On FPGA, both versions of your test fail. The problem is that the keymgr doesn't advance to CreatorRootKey. Instead, it remains at Init.
• With DVSIM, keymgr indeed moves to CreatorRootKey but the simulation ends before OTBN is accessed. Ibex would first check whether OTBN is idle but I never see any TL-UL transactions going into OTBN. The error produced by the simulation is then:

UVM_INFO @ 14791.718670 us: (sw_logger_if.sv:524) [entropy_complex_dbg_sim_dv(sw/device/tests/entropy_complex_dbg.c:165)] Coming out of SW Reset.
UVM_INFO @ 19609.148670 us: (sw_logger_if.sv:370) [tb.u_sim_sram.u_sim_sram_if.u_sw_logger_if.construct_log_and_print.unmblk1.unmblk1.unmblk1.isolation_thread.unmblk1.unmblk1] String arg at addr 20008408: Internal
       5: sw_log.format = $sformatf(sw_log.format, `_ADD_ARGS(5));
                                  |
xmsim: *W,SYSFMW (/home/pirmin/ot/opentitan/scratch/entropy-complex-dbg-3/chip_earlgrey_asic-sim-xcelium/default/src/lowrisc_dv_sw_logger_if_0/sw_logger_if.sv,444|34): $psprintf/$sformatf: Illegal format ignored  %0c.
       5: sw_log.format = $sformatf(sw_log.format, `_ADD_ARGS(5));
                                  |
xmsim: *W,SYSFMW (/home/pirmin/ot/opentitan/scratch/entropy-complex-dbg-3/chip_earlgrey_asic-sim-xcelium/default/src/lowrisc_dv_sw_logger_if_0/sw_logger_if.sv,444|34): $psprintf/$sformatf: Illegal format ignored  %0c.
       5: sw_log.format = $sformatf(sw_log.format, `_ADD_ARGS(5));
                                  |
xmsim: *W,SYSFMW (/home/pirmin/ot/opentitan/scratch/entropy-complex-dbg-3/chip_earlgrey_asic-sim-xcelium/default/src/lowrisc_dv_sw_logger_if_0/sw_logger_if.sv,444|34): $psprintf/$sformatf: Illegal format ignored  %0c.
UVM_ERROR @ 19609.148670 us: (sw_logger_if.sv:526) [entropy_complex_dbg_sim_dv(sw/device/tests/entropy_complex_dbg.c:173)] CHECK-STATUS-fail: MK@:1 = Internal
UVM_INFO @ 19609.148670 us: (uvm_report_catcher.svh:705) [UVM/REPORT/CATCHER] 

Do you have any idea what the problem could be with DVSIM?

[vogelpi]

I think I got a bit closer: keymgr produces an error code both on FPGA and in simulation. The error code is 0x2 which according to the doc stands for:

2   rw1c    0x0 INVALID_SHADOW_UPDATE   An error observed during shadow register updates, asynchronous error
1   rw1c    0x0 INVALID_KMAC_INPUT  Invalid data issued to kmac interface, synchronous error
0   rw1c    0x0 INVALID_OP  Invalid operation issued to key manager, synchronous error

invalid KMAC input.

[moidx]

Is it failing at this check?

TRY(sc_keymgr_state_check(kScKeymgrStateCreatorRootKey));

[vogelpi]

Yes, that's the failing check @moidx .

[vogelpi]

After many many experiments and discussions with @timothytrippel , we haven't been able to reproduce the original issue again. Neither in simulation nor on FPGA. Still, I think it's useful to report the findings and document what we've tried.

Starting point

• As stated earlier, the issue was first faced by @timothytrippel when working on #22714. To work around the issue, @timothytrippel added commit 4fd94db59a656b28be60db223f1698d5b397904a to this PR which moves the loading of the OTBN services program to before reconfiguring the entropy complex and starting keymgr operations.
• In parallel, @h-filali was working on a CSRNG RTL change (#22114, commit 903b31917104b6d9e22f0eb41941a72415109a8a) and noticed CI failures in the //sw/device/silicon_creator/manuf/skus/earlgrey_a0/sival_bringup:ft_provision_fpga_cw310_sival test. Closer inspection revealed a very similar hang issue.
• To allow @h-filali 's PR passing CI, @timothytrippel did another PR (#22716, commit 667b717d38890a04fb2fc29065d4fdd068b23897) to reduce the pressure on CSRNG and ENTROPY_SRC by doing less reseeds.
• Later, it was found that keymgr also contributed to this problem as it consumed quite a lot of entropy once enabled. To fix this, @moidx implemented a configuration change in ROM_EXT to set the reseed interval of keymgr to the max value and further increase the reseed interval of EDN0 (#22944 and #22972). In parallel, we also fixed the keymgr hardware (#22972).

What we've tried

• We've experimented with simulation using @timothytrippel 's stripped down example test https://github.com/timothytrippel/opentitan/tree/entropy-complex-dbg as well as FPGA but we had no success so far.
• In both cases, we went back to 903b31917104b6d9e22f0eb41941a72415109a8a (@h-filali's CSRNG change) and then reverted 4fd94db59a656b28be60db223f1698d5b397904a and 667b717d38890a04fb2fc29065d4fdd068b23897 (@timothytrippel 's software changes).
• We've tried loading bitstreams from the online bitstream cache as well as generating new ones based on the checkout out source tree.
• The keymgr hardware & software changes mentioned above where not in the tested source tree (they were merged much later than the base commit 903b31917104b6d9e22f0eb41941a72415109a8a).
• We've tried making the tests consume even more entropy by further reducing the reseed interval on both EDNs and by also reducing the generate lengths.
• The test always kept passing, i.e., we couldn't reproduce the failures.

Background Information

• @timothytrippel reported that OTBN execution hangs during the UDS attestation (ECC P256) (see https://github.com/lowRISC/opentitan/pull/22716#issue-2251855658). This was confirmed by using JTAG/OpenOCD/GDB.
• We first suspected that the problem occurs at the OTBN execution start when OTBN performs a reseed of the internal PRNG over URND (connected to EDN0). However, on FPGA only we have a modification in place to not perform this reseed at application start to simplify trace alignment for SCA experiments (the reseeding operation leads to a non-deterministic delay at application start).
• Further discussion confirmed that the problem occurs when performing the secure wipe of OTBN DMEM and IMEM before loading the application. This operation also requires entropy, but the entropy is not consumed by OTBN but instead OTP_CTRL which is responsible for generating new scrambling keys for OTBN.
• Internally, OTP_CTRL has multiple entropy consumers all sharing a common interface to EDN0. One consumer is the KDI module responsible for generating scrambling keys (see otp_ctrl_kdi.sv). Per scrambling key, OTP_CTRL requests 4x 64-bit of entropy (see https://opentitan.org/book/hw/ip/otp_ctrl/doc/theory_of_operation.html#scrambling-datapath). OTBN, requires 2 scrambling keys (one for IMEM, one for DMEM).
• The second entropy consumer inside OTP_CTRL is the LFSR-based timer for triggering periodic consistency and integrity checks in OTP (see otp_ctrl_lfsr_timer.sv). The LSBs of that LFSR are reseeded with fresh entropy from EDN0 after consuming LfsrUsageThreshold ( = 16) values from the LFSR. The time it takes to consume these 16 values depends on the content of the LFSR itself. On FPGA, this is ultimately deterministic as we don't have a real RNG on FPGA. However, it depends on many factors: random netlist constants and software timing. So it ultimately depends on the exact state of the repo when the FPGA bitstream is generated.
• The background and consistency checks can be disabled using CSRs (e.g. https://opentitan.org/book/hw/ip/otp_ctrl/doc/registers.html#consistency_check_period--consistency_check_period) and we don't currently seem to enable them in ROM/ROM_EXT currently.
• The checks can also be triggered explicitly using the CHECK_TRIGGER CSR. This will also advance the LFSR. So after 16 checks we would get a reseed as well. Also this currently doesn't seem to happen.
• OTP_CTRL is in a different clock domain compared to OTBN and the EDNs. It might be that we ran into a CDC issue here.

So to summarize, we've done a lot attempting to reproduce the issue but everything failed. Given how hard it is to reproduce this failure I am thinking that this was probably a sporadic FPGA issue happening for some time but not something we have to keep worrying about. There is one last hope which is to retrieve and retry an FPGA bitstream that revealed the issue previously. @h-filali might still have one, I need to check with him once he's back early next week.

[timothytrippel]

Thanks for all the debugging and documenting this @vogelpi ! I think this sounds like a reasonable course of action for now.

[vogelpi]

We've discussed in the triage meeting to extend the edn_csrng_concurrency test by:

• randomizing the entropy reseed intervals and generate lengths
• initiate AES, KMAC, KEYMGR PRNG reeseeds in software to push the entropy consumption up in general

We can then observe the regression dashboard to see how things evolve.

[vogelpi]

The PR to extend the csrng_edn_concurrency test is here: #23277

[andreaskurth]

next: could increase the number of tests or the concurrent CSRNG/EDN executions in nightlies. other than that we're done

[vogelpi]

PR 23314 which adds some further optimizations to speed up the test and increases the number of seeds in the nightlies has been merged now. We'll keep observing the nightlies to see if any failures pop up. I am closing this issue now.