Cosmo BRM13250012 is seemingly dead

[mkeeter]

While testing #2192, we saw Cosmo BRM13250012 (cubby 15 in London) disappear midway through the RoT update:

matt@castle ~ $ pilot sp exec -e "update rot 1 /staff/matt//hubris-2192/oxide-rot-1-cosmo-b.zip" BRM13250012
Aug 13 15:08:39.613 INFO creating SP handle on interface london_sw0tp0, component: faux-mgs
Aug 13 15:08:39.616 INFO initial discovery complete, addr: [fe80::aa40:25ff:fe04:402%3]:11111, interface: london_sw0tp0, socket: control-plane-agent, component: faux-mgs
Aug 13 15:08:39.639 INFO generated update ID, id: 1ba66d0f-d11d-4b17-b102-8cea44dbe63d, component: faux-mgs
Aug 13 15:08:39.664 INFO starting update, total_size: 214984, id: 1ba66d0f-d11d-4b17-b102-8cea44dbe63d, component: rot, interface: london_sw0tp0, socket: control-plane-agent, component: faux-mgs
Aug 13 15:08:39.670 INFO update in progress, total_size: 214984, bytes_received: 0, component: faux-mgs
Aug 13 15:08:39.671 INFO update preparation complete, update_id: 1ba66d0f-d11d-4b17-b102-8cea44dbe63d, interface: london_sw0tp0, socket: control-plane-agent, component: faux-mgs
Aug 13 15:08:40.677 INFO update in progress, total_size: 214984, bytes_received: 25428, component: faux-mgs
Aug 13 15:08:41.703 INFO update in progress, total_size: 214984, bytes_received: 50856, component: faux-mgs
Aug 13 15:08:42.709 INFO update in progress, total_size: 214984, bytes_received: 76284, component: faux-mgs
Aug 13 15:08:53.430 ERRO update failed, error: RPC call failed (gave up after 5 attempts), id: 1ba66d0f-d11d-4b17-b102-8cea44dbe63d, interface: london_sw0tp0, socket: control-plane-agent, component: faux-mgs

At this point, the SP had been updated with the a image from that branch. Note that we didn't actually select the new RoT image; the system dropped dead midway through flashing it.

Since then, we have not managed to get it to show up on the network, either from castle (pilot -rlondon sp ls) or the switch zone. The host is also not visible, and drive lights are off.

Manually removing + reracking the sled doesn't recover the system. We see the chassis LED turn on about 8-10 seconds after it's reracked, but it doesn't come up on the network.

@leftwo is going to extract the sled into a benchtop debugging setup, so we can probe the SP and see what's going on.

[mkeeter]

Attaching a programming header with the sled still in London, the SP is Really Quite Dead:

alan@alfred ~ $ pfexec humility -p1fc9:0143:4ZQNLXC4KLURU -a //staff/matt/hubris-2192/cosmo-a-dev.zip probe
humility: attached to 1fc9:0143:4ZQNLXC4KLURU via CMSIS-DAP
humility probe failed: An error with the usage of the probe occured

Caused by:
    Operation timed out

Reseating the connector (and cycling the sled) brought it back

alan@alfred ~ $ pfexec humility -p1fc9:0143:4ZQNLXC4KLURU -a //staff/matt/hubris-2192/cosmo-a-dev.zip probe
humility: attached to 1fc9:0143:4ZQNLXC4KLURU via CMSIS-DAP
humility:        probe => CMSIS-DAP, VID 1fc9, PID 0143
humility: probe serial => 4ZQNLXC4KLURU
humility:         core => Cortex-M7
humility: manufacturer => STMicroelectronics
humility:         chip => STM32H7, revision 0x2003
humility:       status => executing, debug halt
humility:  debug units => CSTF(x2) CTI(x2) DWT ETM FPB ITM SCS SWO TMC TPIU
humility:         CSTF => 0x5c004000, 0x5c013000
humility:          CTI => 0x5c011000, 0xe0043000
humility:          DWT => 0xe0001000
humility:          ETM => 0xe0041000
humility:          FPB => 0xe0002000
humility:          ITM => 0xe0000000
humility:          SCS => 0xe000e000
humility:          SWO => 0x5c003000
humility:          TMC => 0x5c014000
humility:         TPIU => 0x5c015000
humility:           R0 => 0x2406c900   <- idle: 0x2406c800+0x100
humility:           R1 => 0x2406c900   <- idle: 0x2406c800+0x100
humility:           R2 => 0x0        
humility:           R3 => 0x0        
humility:           R4 => 0x0        
humility:           R5 => 0x0        
humility:           R6 => 0x0        
humility:           R7 => 0x0        
humility:           R8 => 0x0        
humility:           R9 => 0x0        
humility:          R10 => 0x0        
humility:          R11 => 0x0        
humility:          R12 => 0x0        
humility:           SP => 0x2406c900   <- idle: 0x2406c800+0x100
humility:           LR => 0x805d04f    <- idle: _start+0x4f
humility:           PC => 0x805d052    <- idle: main+0x2
humility:          PSR => 0x61000000 
humility:          MSP => 0x240003b0 
humility:          PSP => 0x2406c900 
humility:          SPR => 0x7000000

But it dropped into the failed state again within ~2 minutes.

We are going to fully extract it from London for further debugging.

[mkeeter]

This is now in the mb-2 test harness:

matt@jeeves ~ () $ pfexec humility --target mb-2-sp --archive /staff/matt/hubris-2192/cosmo-a-dev.zip tasks
humility: WARNING: archive on command-line overriding archive in environment file
humility: attached to 1fc9:0143:V1WU5NQAKC3YW via CMSIS-DAP
system time = 245060
ID TASK                       GEN PRI STATE
 0 jefe                         0   0 recv, notif: fault timer(T+40)
 1 net                          0   5 recv, notif: eth-irq(irq61) wake-timer(T+148)
 2 sys                          0   1 recv, notif: exti-wildcard-irq(irq6/irq7/irq8/irq9/irq10/irq23/irq40)
 3 spi2_driver                  0   3 recv
 4 spi3_driver                  0   3 recv
 5 i2c_driver                   0   3 recv
 6 packrat                      0   1 recv
 7 thermal                      0   8 recv, notif: timer(T+655)
 8 power                        0   8 recv, notif: timer(T+175)
 9 hiffy                        0   7 notif: bit31(T+228)
10 cosmo_seq                    0   7 recv, notif: timer(T+25)
11 ignition_flash               0   7 recv
12 spartan7_loader              0   4 recv
13 hash_driver                  0   2 recv
14 hf                           0   6 recv, notif: timer
15 update_server                0   3 recv
16 sensor                       0   4 recv
17 host_sp_comms                0   9 recv, notif: jefe-state-change usart-irq(irq71) multitimer control-plane-agent
18 udpecho                      0   6 notif: socket
19 udpbroadcast                 0   6 notif: bit31(T+112)
20 control_plane_agent          0   8 recv, notif: usart-irq(irq37) socket timer
21 sprot                        0   4 recv
22 validate                     0   5 recv
23 vpd                          0   4 recv
24 user_leds                    0   2 recv, notif: timer
25 dump_agent                   0   6 recv, notif: socket
26 spd                          0   7 recv, notif: timer(T+175)
27 auxflash                     0   3 recv
28 idle                         0  15 RUNNING
29 udprpc                       0   6 notif: socket
30 fmc_demo                     0   6 recv, notif: socket

[cbiffle]

We moved this sled back over into London and have been able to reliably reproduce the failure.

What we know at this point:

1. The Cosmo is installed in slot 17 on London.
2. It has a SWD probe attached to the SP. This will interfere with some RoT operation, but is unfortunately necessary to catch the failure.
3. When loaded with @mkeeter's measurement handoff branch and reset, the system hangs between 60 and 150 seconds after start. The failures seem to be clustered slightly closer to 60s but we don't have enough data to say for sure.
4. When loaded with current master, the system has not been caught hanging; that is, it appears stable.
5. The hang causes the CPU to fail to halt, which suggests that it's been stopped during operation (i.e. the C_HALT bit in the DHCSR is never echoed back as S_HALT). This is consistent with being stalled by the FMC peripheral in the hang we hit before.
6. Resetting the machine under vector-catch to preserve as much state as possible shows a system in an unremarkable state, with no particular smoking gun.

The fact that Matt's reset changes seem to affect reliablity is a surprise, since the point where it resets the processor is before we've so much as set up the external oscillator, much less exposed any FMC-related signals. But, it's having some side effect on the system that seems to improve our ability to reproduce the failure. Fun.

I am rebuilding Matt's changes with the processor's dcache disabled, since that makes reconstructing state in these failures easier. I'll report back if I catch it in the act.

Debugging this issue has been complicated by the USB stack on the Illumos butler crapping itself repeatedly. I've brought my Linux laptop over to keep the number of simultaneous issues being debugged to ~1, and the probe has been stable.

[cbiffle]

Alright, so, weirdly:

• Matt's build crashes more reliably than mine at the same commit hash
• But my build at 48f6555 does crash, just takes longer
• I've recorded a dump, but
• If I turn off dcache to make the dump more reliable, the system no longer crashes.

wheeeee

[mkeeter]

The debug call from this afternoon is qxo-ibho-ukw, for those seeking the recording!

[mkeeter]

I have flashed an image from this branch, commit f60e1bf

matt@ferguson ~ $ pfexec ./humility -a /staff/matt/hubris-2198/build-cosmo-a-dev-image-default.zip flash

There's a simple change versus #2192: we set the PROGRAM_L GPIO before resetting. This should not change anything, but it's an incremental step – we would like to test whether clearing PROGRAM_L (which resets the bitstream) changes behavior. Before doing that, we want to confirm that the additional GPIO wrangling doesn't make the issue disappear.

[mkeeter]

That test did not hang after a few resets and 3096491 ms of waiting. Reflashing the image from /staff/matt/hubris-2192/cosmo-a-dev.zip, it hung within ~5 minutes.

[labbott]

I've gotten it to reproduce more reliably with some scripting. I've been able to reproduce it after anywhere from 2 to 48 minutes. The following still seem to reproduce the issue

• Setting PROGRAM_L at boot to clear the FPGA
• Removing thermal temperature polling in spd
• Stop polling in the sequencer after we hit A0Hp (i.e. don't touch FMC bus once we're all done booting)

[mkeeter]

I think you tested this, but can you confirm that clearing PROGRAM_L also reproduces the issue? (it's active low, so setting it high during the SP reset doesn't actually reset the FPGA bitstream)

[labbott]

I think you tested this, but can you confirm that clearing PROGRAM_L also reproduces the issue? (it's active low, so setting it high during the SP reset doesn't actually reset the FPGA bitstream)

Correct, I tested both cases and it still reproduced (by setting PROGRAM_L I meant setting it to the value that is expected to reset the bitstream. I love ambiguous language with pins)

[labbott]

Collecting several dumps, we were often waiting in sprot to read data from the RoT. I hacked up control-plane-agent to never actually call sprot and return dummy data. That also hung and this time we seemed to be running in thermal when we crashed (maybe calling out to i2c?)

[labbott]

In the STM32H7 RM0433 Table 2.3.2 the default attributes for the FMC are Normal and execute allowed. This means the CPU is allowed to speculate into this area. The MPU disables access for tasks unless the system has requested access but the kernel has full access. As an experiment, I turned the NULL region for the kernel into one that covers the FMC area:

diff --git a/sys/kern/build.rs b/sys/kern/build.rs
index c009b130..0e8d52a8 100644
--- a/sys/kern/build.rs
+++ b/sys/kern/build.rs
@@ -77,13 +77,13 @@ fn process_config() -> Result<Generated> {
     region_table.insert(
         RegionKey::Null,
         RegionConfig {
-            base: 0,
-            size: 32,
+            base: 0x6000_0000,
+            size: 0x1000_0000,
             attributes: RegionAttributes {
-                read: false,
-                write: false,
+                read: true,
+                write: true,
                 execute: false,
-                special_role: None,
+                special_role: Some(SpecialRole::Device),
             },
         },
     );

The issue hasn't reproduced after several hours. If I change the base address to something that isn't the FMC region (say 0x7000_0000 I saw failures within 20 minutes so I'm reasonably confident this change is correlated with preventing the issue as opposed to making it go away because CPU timing. I think this is showing that whatever is causing the CPU hang is a speculative access.

[mkeeter]

Looking through the datasheet, I noticed something interesting.

We're using the FPGA in PSRAM mode, which puts it at 0x60000000 in Normal, Write-back, write allocate cache attribute, Execute Allowed. As you said, this allows for speculation into the area.

However, it's also possible to – while remaining in PSRAM mode – to remap PSRAM 1 Bank 1 to address 0xC0000000, which is Device, Execute Never:

This is done using the BMAP bits in FMC_BCR1:

If my mental model is correct, this should fix speculation without having to burn an MPU region (or mess with FPGA behavior such that it idles with !WAIT).

[labbott]

This should be fixed by #2211