Crucible panicked after hitting IO completion error

[askfongjojo]

I have some running instances returned "Failed Dependency" error when I tried to stop or reboot them (see oxidecomputer/omicron#5705 for the context).
Looking at the propolis log for one of them, I saw that it panicked at one point:

BRM42220009 # grep IO /pool/ext/d0584f4a-20ba-436d-a75b-7709e80deb79/crypt/debug/oxz_propolis-server_5317472d-c334-451e-ad6a-7c184289bbf7/system-illumos-propolis-server:default.log.1714980545 | looker
07:23:48.646Z INFO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): Scrubs from block 0 to 4194304 in (256) 131072 size IOs pm:25
07:29:03.883Z ERRO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): IO completion error: missing 14411 
     = downstairs
    client = 2
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60

The complete log file is attached here:
system-illumos-propolis-server:default.log.1714980545.log

[mkeeter]

There's an informative comment right above that assertion:

            /*
             * This assertion is only true for a limited time after
             * the downstairs has failed.  An old in-flight IO
             * could, in theory, ack back to us at some time
             * in the future after we cleared the completed.
             * I also think this path could be  possible if we
             * are in failure mode for LiveRepair, as we could
             * get an ack back from a job after we failed the DS
             * (from the upstairs side) and flushed the job away.
             */

[askfongjojo]

I hit this issue again when provisioning new disks/instances en masse (120 copies of the same thing) using Terraform. So far, the activities running in parallel with TF provisioning that triggered the scrubbing job failure were:

1. disk provisioning activities (a script that created 10x 150Gb disk sequentially)
2. executing bonnie++ on multiple VMs that are located across different sleds in the rack

If there are any specific probes I should apply to better understand the resource utilization situation (e.g. memory or cpu), please let me know.

[leftwo]

Just to be clear, I don't think the error is from a scrubbing job failure, at least not directly.
The panic looks to happen because Crucible is receiving a completion for a job ID that it
does not recognize.

Also in the logs, we do get a timeout to one of the downstairs (2):

07:27:51.035Z WARN propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): timeout 1/3  
  downstairs client = 2 session_id = 023341a5-1224-42d4-a5eb-30244dae3a60

This eventually leads to the upstairs taking the downstairs offline:

07:28:21.038Z WARN propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): timeout 3/3                              
     = downstairs                                                                                                            
    client = 2                                                
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60
07:28:21.039Z WARN propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): inactivity timeout
     = downstairs                                             
    client = 2                                                                                                               
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60
07:28:21.040Z WARN propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): client task is sending Done(Timeout)     
     = downstairs
    client = 2                                                
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60                                                                        
07:28:21.040Z WARN propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): downstairs task for 2 stopped due to Timeout                
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60         
07:28:21.040Z INFO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): Gone missing, transition from Active to Offline                                                                                                                       
     = downstairs                                             
    client = 2                                                                                                               
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60

The downstairs does come back almost right away:

07:28:31.042Z INFO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): connecting to [fd00:1122:3344:104::5]:190
08
     = downstairs
    client = 2
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60
07:28:31.043Z INFO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): ds_connection connected from Ok([fd00:112
2:3344:107::1:245]:34122)
     = downstairs
    client = 2
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60
07:28:31.050Z INFO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): downstairs client at Some([fd00:1122:3344
:104::5]:19008) has region UUID 56748c4c-bb25-425a-808a-8c201dd16326
     = downstairs
    client = 2
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60
07:28:31.050Z INFO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): Returning UUID:56748c4c-bb25-425a-808a-8c
201dd16326 matches
     = downstairs
    client = 2
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60
07:28:31.051Z INFO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): send last flush ID to this DS: 14405
     = downstairs
    client = 2
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60
07:28:31.051Z INFO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): Replied this last flush ID: 14405
     = downstairs
    client = 2
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60
07:28:31.051Z INFO propolis-server (crucible-fda6b60b-1ea5-4d90-8610-64e691b45879): ds_transition from Offline to Replay
     = downstairs
    client = 2
    session_id = 023341a5-1224-42d4-a5eb-30244dae3a60

So, something else is in play here.
However, we should not be hitting the panic.

[leftwo]

Another oddity here, when downstairs 2 returns, we tell it the last flush ID was 14405.
However, the panic comes when we process a higher ID job:
IO completion error: missing 14411

It seems like job 14411 should still be either active or recently completed if job 14405
is the flush from where we start a replay at. So, there is more to discover here.

[leftwo]

Possibly related to a downstairs not responding, (or at least a tracking issue for that) #1289