A downstairs cant complete a Live Repair.

[leftwo]

On Madrid, I have 191 instances,
190 of them are running IO,
2 CPUs, 8G memory.
They all have a single 4GiB (512b block size) disk and are doing IO to ~2GiB of that disk.

I reboot a sled, and instances move around and restart, but there are a few instances that
just can't get through Live Repair and have all three downstairs back.

Once such instance the upstairs connects to the failed downstairs.
It begins Live Repair, but gets a failure before it can complete the repair:

2026-04-14 03:13:18.494Z INFO propolis-server/12822 (vm_state_driver) on oxz_propolis-server_5518798c-5f53-4816-b00f-f61c4507c6e3: Repair for extent 5 s:2 d:[ClientId(1)]
     = downstairs
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933
2026-04-14 03:13:18.494Z INFO propolis-server/12822 (vm_state_driver) on oxz_propolis-server_5518798c-5f53-4816-b00f-f61c4507c6e3:  1813552 final dependency list [[JobId(1813551)]]
     = downstairs
    client = 1
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933
2026-04-14 03:13:18.999Z WARN propolis-server/12822 (vm_state_driver) on oxz_propolis-server_5518798c-5f53-4816-b00f-f61c4507c6e3: flush check fired despite having jobs; resetting it
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933

More flush check failed messages, then:

8798c-5f53-4816-b00f-f61c4507c6e3: flush check fired despite having jobs; resetting it
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933
2026-04-14 03:13:32.839Z WARN propolis-server/12822 (vm_state_driver) on oxz_propolis-server_5518798c-5f53-4816-b00f-f61c4507c6e3: flush check fired despite having jobs; resetting it
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933
2026-04-14 03:13:33.126Z WARN propolis-server/12822 (vm_state_driver) on oxz_propolis-server_5518798c-5f53-4816-b00f-f61c4507c6e3: timeout 1/3
     = downstairs
    client = 1
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933
2026-04-14 03:13:33.521Z WARN propolis-server/12822 (vm_state_driver) on oxz_propolis-server_5518798c-5f53-4816-b00f-f61c4507c6e3: downstairs disconnected
     = downstairs
    client = 1
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933
2026-04-14 03:13:33.521Z ERRO propolis-server/12822 (vm_state_driver) on oxz_propolis-server_5518798c-5f53-4816-b00f-f61c4507c6e3: job id 1813552 saw error RepairStreamError("repair File { fd: 76, read: true, write: true }: stream error: reqwest::Error { kind: Decode, source: reqwest::Error { kind: Body, source: TimedOut } }")
     = downstairs
    client = 1
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933
2026-04-14 03:13:33.521Z WARN propolis-server/12822 (vm_state_driver) on oxz_propolis-server_5518798c-5f53-4816-b00f-f61c4507c6e3: client task is sending Done(Finished)
     = downstairs
    client = 1
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933
2026-04-14 03:13:33.521Z ERRO propolis-server/12822 (vm_state_driver) on oxz_propolis-server_5518798c-5f53-4816-b00f-f61c4507c6e3: DS Reports error RepairStreamError("repair File { fd: 76, read: true, write: true }: stream error: reqwest::Error { kind: Decode, source: reqwest::Error { kind: Body, source: TimedOut } }") on job 1813552, DownstairsIO { work: ExtentLiveRepair { dependencies: [JobId(1813551)], extent: ExtentId(5), source_downstairs: ClientId(2), source_repair_address: [fdd5:cfdb:cca5:102::6]:23004, repair_downstairs: [ClientId(1)] }, state: ClientData([Done, InProgress, Done]), res: None, acked: false, replay: false, data: None, io_limits: ClientMap(ClientData([None, None, None])) } EC
     = downstairs
    client = 1
    session_id = 750e20f9-bfab-4307-bc9b-2288b2676933

The downstairs reports:

03:13:13.123Z INFO crucible: accepted connection from [fdd5:cfdb:cca5:103::1:42a]:64975                                                
    task = main                                                                                                                        
03:13:13.123Z INFO crucible: connection ([fdd5:cfdb:cca5:103::1:42a]:64975): tasks spawned                                             
    id = 277                                                                                                                           
03:13:13.123Z INFO crucible: Connection request from c6c4571c-d3b8-4dcd-9f28-fe8e067fb010 with version 13                              
03:13:13.123Z INFO crucible: upstairs UpstairsConnection { upstairs_id: c6c4571c-d3b8-4dcd-9f28-fe8e067fb010, session_id: 750e20f9-bfab
-4307-bc9b-2288b2676933, generation: 17 } connected, version 13                                                                        
03:13:13.126Z INFO crucible: UpstairsConnection { upstairs_id: c6c4571c-d3b8-4dcd-9f28-fe8e067fb010, session_id: 750e20f9-bfab-4307-bc9
b-2288b2676933, generation: 17 } is now active (read-write)
03:13:13.184Z INFO crucible: Current flush_numbers [0..12]: [35411, 38793, 38890, 38793, 27421, 38824, 38400, 38548, 37731, 37074, 3278
8, 32786]
03:13:13.190Z WARN crucible: 1812880 job ELiveReopen waiting on 1 deps
    role = work
    upstairs_id = c6c4571c-d3b8-4dcd-9f28-fe8e067fb010
03:13:13.241Z WARN crucible: 1812908 job ELiveReopen waiting on 1 deps
    role = work
    upstairs_id = c6c4571c-d3b8-4dcd-9f28-fe8e067fb010
03:13:13.264Z WARN crucible: 1812914 job Flush waiting on 1 deps
    role = work
    upstairs_id = c6c4571c-d3b8-4dcd-9f28-fe8e067fb010
03:13:14.614Z WARN crucible: 1813077 job ELiveReopen waiting on 1 deps
    role = work
    upstairs_id = c6c4571c-d3b8-4dcd-9f28-fe8e067fb010
03:13:16.785Z WARN crucible: 1813342 job ELiveReopen waiting on 1 deps
    role = work
    upstairs_id = c6c4571c-d3b8-4dcd-9f28-fe8e067fb010
03:13:18.014Z WARN crucible: 1813530 job ELiveReopen waiting on 1 deps
    role = work
    upstairs_id = c6c4571c-d3b8-4dcd-9f28-fe8e067fb010
03:13:18.058Z WARN crucible: 1813554 job ELiveReopen waiting on 1 deps
    role = work
    upstairs_id = c6c4571c-d3b8-4dcd-9f28-fe8e067fb010
03:13:18.480Z WARN crucible: 1813562 job Flush waiting on 1 deps
    role = work
    upstairs_id = c6c4571c-d3b8-4dcd-9f28-fe8e067fb010
03:13:18.495Z INFO crucible: Created copy dir "/data/regions/659a224c-a175-4859-8275-baafbe548590/00/000/005.copy"
03:13:18.518Z INFO crucible: eid:5 Found repair files: ["005"]
03:13:33.520Z WARN crucible: handle_frame returns error proc_frame
     
    Caused by:
        Repair has failed, exiting task; disconnecting
03:13:33.522Z INFO crucible: upstairs UpstairsConnection { upstairs_id: c6c4571c-d3b8-4dcd-9f28-fe8e067fb010, session_id: 750e20f9-bfab
-4307-bc9b-2288b2676933, generation: 17 } (ConnectionId(277)) removed, 2 jobs left
03:13:33.522Z INFO crucible: upstairs UpstairsConnection { upstairs_id: c6c4571c-d3b8-4dcd-9f28-fe8e067fb010, session_id: 750e20f9-bfab
-4307-bc9b-2288b2676933, generation: 17 } (ConnectionId(277)) was previously active, clearing
03:13:33.522Z WARN crucible: got message for disconnected id ConnectionId(277); ignoring
03:13:33.522Z WARN crucible: got message for disconnected id ConnectionId(277); ignoring
03:13:33.522Z WARN crucible: got message for disconnected id ConnectionId(277); ignoring
03:13:33.522Z INFO crucible: got cancelled token; recv_task stopping
    id = 277
    task = recv

[jmpesp]

This ultimately looks timeout related to me: RepairStreamError is due to a TimedOut when streaming bytes from the remote repair server, and I think a failure for this part of the repair means that the Upstairs drops the connection entirely, leading to the

handle_frame returns error proc_frame
     
    Caused by:
        Repair has failed, exiting task; disconnecting

Question is what to do about it. Does it eventually resolve itself?

[leftwo]

I stopped about 25 of my instances and this particular LiveRepair was able to finish.
The sleds are still pretty busy overall:

root@oxz_switch0:~# pilot host exec -c 'uptime' 14-17
14  BRM42220081        ok: 15:14:57    up 16:53,  1 user,  load average: 99.52, 100.53, 101.74
15  BRM42220046        ok: 15:14:58    up 16:19,  1 user,  load average: 88.69, 91.20, 91.47
16  BRM42220007        ok: 15:14:59    up 16:19,  1 user,  load average: 119.92, 121.12, 121.75
17  BRM42220004        ok: 15:14:59    up 15:13,  2 users,  load average: 23.96, 23.59, 23.49

I still have six instances where a LiveRepair has not been able to finish. This is ~12 hours after having rebooted a sled, which would have been the start of the LiveRepair.

[leftwo]

James posited: I wonder if the 15 second timeout default bit us here

And, looking at out our downstairs log:

03:13:18.518Z INFO crucible: eid:5 Found repair files: ["005"]
03:13:33.520Z WARN crucible: handle_frame returns error proc_frame

That looks to be 15 seconds.
So, there is some amount of overall system saturation that was preventing the repair from finishing in the 15 second window that we have open for the transfer to take. Usually this transfer can finish in under a second.

A one second iostat on the sled with downstairs shows:

                    extended device statistics              
    r/s    w/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
  460.0  145.0   57.4    6.9  0.0  0.2    0.0    0.3   0  16 oxp_fb9b219d-e4b2-40ad-a2b5-92
 1379.9 3494.8  172.1  415.7 103.4  0.9   21.2    0.2  34  56 oxp_31dff88b-3435-4317-ac0c-c6
 1058.9 7487.6  132.1  779.4 218.5  1.1   25.6    0.1  65  73 oxp_9d0b45b5-3073-47f3-8374-e6
  881.0 4289.8  109.8  456.1 111.7  0.8   21.6    0.1  38  53 oxp_55ff5ef4-7950-43c8-a288-dd
 1789.9 2515.9  223.7  296.2 78.8  0.9   18.3    0.2  24  60 oxp_babdec50-930f-4d43-98f4-05
  724.0 5732.7   90.5  677.1 153.2  0.9   23.7    0.1  55  64 oxp_02f510f4-85a2-441d-aa00-0b
  861.0 5875.7  107.4  624.3 174.3  1.1   25.9    0.2  70  76 oxp_71e38eb2-cb44-4998-92b1-77
  874.0 5854.7  109.1  648.9 178.8  0.9   26.6    0.1  53  65 oxp_115a5665-72fe-4ff1-b807-6f
 1281.9 7565.7  159.9  800.7 209.7  1.4   23.7    0.2  69  77 oxp_94b61fb7-47a2-48af-b12c-bf
 1601.9 8101.6  199.9  865.7 234.5  1.4   24.2    0.1  71  87 oxp_0d50b94c-e7e3-4e39-a76f-89

So, it was pretty busy.

Indeed after stopping IO to many of the instances, the downstairs that were stuck in LiveRepair did manage to finish up.