All IO failing after rolling downstairs node reboots

[JustinAzoff]

In trying to reproduce #1788 I put together https://github.com/oxidecomputer/crucible_jepsen

So far I have not triggered that issue, but have been able to reliably trigger an availability issue after restarting each downstairs node.

The jepsen test is doing the following:

On each ds node:

# once during setup
rm -rf /opt/crucible/data
/opt/crucible/crucible-downstairs create -u $random-uuid -d /opt/crucible/data --encrypted

# via smf
/opt/crucible/crucible-downstairs run -p 3810 -d /opt/crucible/data

On the upstairs:

# https://github.com/oxidecomputer/crucible/blob/rest-server-for-jepsen/rest_server/src/main.rs
/opt/crucible/crucible-rest-server -g 1 --key rgcfQ6nDFT5ZuMeqrUGBW2txZ9tZh/zQUc9ZnhnwDH4= --listen 0.0.0.0:9999 --target=172.21.252.170:3810 --target=172.21.252.173:3810 --target=172.21.252.174:3810

Then, during the test, ds nodes are randomly rebooted using:

mdb -kwe 'clock/W -1'

For the test:

172.21.252.194: upstairs / crucible-rest-server
172.21.252.170: ds
172.21.252.173: ds
172.21.252.174: ds

Most recent test:

$ lein run  test --nodes-file my.nodes  --concurrency 100 --time-limit 1800
# wait 30 minutes

The issue is easy to see in the graphs jepsen produces:

The left edge of the gray sections at the top correspond to the reboot being triggered. Jepsen isn't directly controlling the VM coming back up, so the width of the gray section is approximate.. the actual 'outage' is however long the node takes to reboot and smf to restart the downstairs.

$cat crucible_jepsen_20251021T134348/jepsen.log |egrep -e Relat -e 'Rebooting'|sed "s/.clojure.*ble://"
2025-10-21 13:44:01,364{GMT}	INFO	[jepsen test runner] jepsen.core: Relative time begins now
2025-10-21 13:46:31,607{GMT}    INFO     172.21.252.173 Rebooting in 5 seconds
2025-10-21 13:49:36,963{GMT}    INFO     172.21.252.170 Rebooting in 5 seconds
2025-10-21 13:52:42,335{GMT}    INFO     172.21.252.173 Rebooting in 5 seconds
2025-10-21 13:55:47,718{GMT}    INFO     172.21.252.174 Rebooting in 5 seconds
2025-10-21 13:58:53,090{GMT}    INFO     172.21.252.170 Rebooting in 5 seconds
2025-10-21 14:01:58,427{GMT}    INFO     172.21.252.173 Rebooting in 5 seconds

first failed writes were at 13:51 after the second node reboot:

$ cat crucible_jepsen_20251021T134348/jepsen.log |grep :fail|grep :write|head
2025-10-21 13:51:15,370{GMT}    INFO    [jepsen worker 26] jepsen.util: 26      :fail   :write  [13 8841]       500
2025-10-21 13:51:30,380{GMT}    INFO    [jepsen worker 45] jepsen.util: 45      :fail   :write  [22 4690]       500
2025-10-21 13:51:45,390{GMT}    INFO    [jepsen worker 10] jepsen.util: 10      :fail   :write  [5 3185]        500
2025-10-21 13:52:00,401{GMT}    INFO    [jepsen worker 37] jepsen.util: 37      :fail   :write  [18 8880]       500
2025-10-21 13:52:30,423{GMT}    INFO    [jepsen worker 86] jepsen.util: 86      :fail   :write  [43 9875]       500
2025-10-21 13:53:00,445{GMT}    INFO    [jepsen worker 77] jepsen.util: 77      :fail   :write  [38 2919]       500

reads began failing at 13:56 after the third node was rebooted (fourth reboot overall)

$ cat crucible_jepsen_20251021T134348/jepsen.log |grep :fail|grep :read|head
2025-10-21 13:56:07,813{GMT}    INFO    [jepsen worker 47] jepsen.util: 47      :fail   :read   [23 nil]        500
2025-10-21 13:56:07,814{GMT}    INFO    [jepsen worker 17] jepsen.util: 17      :fail   :read   [8 nil] 500
2025-10-21 13:56:07,814{GMT}    INFO    [jepsen worker 74] jepsen.util: 74      :fail   :read   [37 nil]        500
2025-10-21 13:56:07,814{GMT}    INFO    [jepsen worker 69] jepsen.util: 69      :fail   :read   [34 nil]        500
2025-10-21 13:56:07,814{GMT}    INFO    [jepsen worker 64] jepsen.util: 64      :fail   :read   [32 nil]        500
2025-10-21 13:56:07,815{GMT}    INFO    [jepsen worker 34] jepsen.util: 34      :fail   :read   [17 nil]        500
2025-10-21 13:56:07,815{GMT}    INFO    [jepsen worker 50] jepsen.util: 50      :fail   :read   [25 nil]        500
2025-10-21 13:56:07,815{GMT}    INFO    [jepsen worker 33] jepsen.util: 33      :fail   :read   [16 nil]        500
2025-10-21 13:56:07,816{GMT}    INFO    [jepsen worker 65] jepsen.util: 65      :fail   :read   [32 nil]        500
2025-10-21 13:56:07,816{GMT}    INFO    [jepsen worker 49] jepsen.util: 49      :fail   :read   [24 nil]        500

$ grep 'All three' crucible_jepsen_20251021T134348/172.21.252.194/opt/crucible/crest.log |head -n 1
{"msg":"All three downstairs require repair","v":0,"name":"crucible","level":40,"time":"2025-10-21T13:56:14.017850081Z","hostname":"jepsen-n4","pid":3951,"":"downstairs","":"downstairs","session_id":"0adf013c-2b49-46cd-8285-ffd06df5b927"}

My understanding is that I am leaving plenty of time between the node reboots and it should have enough time to repair before the next reboot.

crucible_jepsen_20251021T134348.tar.gz

[leftwo]

Do you have the output from dtrace -s tools/get-up-info

Possibly another instance of: dtrace -s tools/up-info.d?
I suspect this is another case of:
#1556

If so, you should test and see if the work in #1784 fixes it.

[JustinAzoff]

I started up a new test with a shorter reboot interval and with the get-up-state.d running in a loop.. this looks like a different issue:

Tue Oct 21 15:05:02 UTC 2025
  PID  SESSION DS0 DS1 DS2   NEXT_JOB  DELTA CONN   ELR   ELC   ERR   ERN
 4462 99940b85 ACT ACT ACT       3171      0    3     0     0     0     0
 4462 99940b85 ACT ACT ACT       3201     30    3     0     0     0     0
 4462 99940b85 ACT ACT ACT       3241     70    3     0     0     0     0
 4462 99940b85 ACT ACT ACT       3281    110    3     0     0     0     0
 4462 99940b85 ACT ACT ACT       3321    150    3     0     0     0     0
 4462 99940b85 ACT ACT OFL       3343    172    3     0     0     0     0
 4462 99940b85 ACT ACT OFL       3392    221    3     0     0     0     0
 4462 99940b85 ACT ACT FLT       3418    247    3     0     0     0     0
 4462 99940b85 ACT ACT FLT       3461    290    3     0     0     0     0
 4462 99940b85 ACT ACT FLT       3507    336    3     0     0     0     0

Tue Oct 21 15:05:13 UTC 2025
  PID  SESSION DS0 DS1 DS2   NEXT_JOB  DELTA CONN   ELR   ELC   ERR   ERN
 4462 99940b85 ACT ACT FLT       3566      0    3     0     0     0     0
 4462 99940b85 ACT ACT FLT       3592     26    3     0     0     0     0
 4462 99940b85 ACT ACT FLT       3638     72    3     0     0     0     0
 4462 99940b85 ACT ACT FLT       3666    100    3     0     0     0     0
 4462 99940b85 ACT ACT  LR       3703    137    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703    137    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703    137    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703    137    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703    137    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703    137    4     1     0     0     0

Tue Oct 21 15:05:25 UTC 2025
  PID  SESSION DS0 DS1 DS2   NEXT_JOB  DELTA CONN   ELR   ELC   ERR   ERN
 4462 99940b85 ACT ACT  LR       3703      0    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703      0    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703      0    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703      0    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703      0    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703      0    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       3703      0    4     1     0     0     0
 4462 99940b85 ACT ACT FLT       3816    113    4     1     0     0     0
 4462 99940b85 ACT ACT FLT       4309    606    4     1     0     0     0
 4462 99940b85 ACT ACT FLT       4347    644    4     1     0     0     0

Tue Oct 21 15:05:36 UTC 2025
  PID  SESSION DS0 DS1 DS2   NEXT_JOB  DELTA CONN   ELR   ELC   ERR   ERN
 4462 99940b85 ACT ACT FLT       4407      0    4     1     0     0     0
 4462 99940b85 ACT ACT FLT       4443     36    4     1     0     0     0
 4462 99940b85 ACT ACT FLT       4483     76    4     1     0     0     0
 4462 99940b85 ACT ACT FLT       4516    109    4     1     0     0     0
 4462 99940b85 ACT ACT FLT       4542    135    4     1     0     0     0
 4462 99940b85 ACT ACT FLT       4578    171    4     1     0     0     0
 4462 99940b85 ACT ACT  LR       4619    212    5     2     0     0     0
 4462 99940b85 ACT ACT  LR       4619    212    5     2     0     0     0
 4462 99940b85 ACT ACT  LR       4619    212    5     2     0     0     0
 4462 99940b85 ACT ACT  LR       4619    212    5     2     0     0     0

and now that a second node rebooted it is in

4462 99940b85 LRR ACT  LR       5513      0    9     5     0     0     0

and now a third put it in

4462 99940b85 FLT FLT LRR       5522      2   10     6     0     0     0
4462 99940b85 LRR LRR LRR       5522      0   12     6     0     0     0

[JustinAzoff]

a ds in this state logs this every 15s or so

{"msg":"handle_frame returns error proc_frame\n\nCaused by:\n    Repair has failed, exiting task; disconnecting","v":0,"name":"crucible","level":40,"time":"2025-10-21T15:38:48.711412197Z","hostname":"jepsen-n2","pid":609}
{"msg":"upstairs UpstairsConnection { upstairs_id: 00000000-0000-0000-0000-000000000000, session_id: fc1083d9-3e52-49b1-b95f-0bf05740a9d9, gen: 1 } (ConnectionId(19)) removed, 2 jobs left","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:48.71151453Z","hostname":"jepsen-n2","pid":609}
{"msg":"upstairs UpstairsConnection { upstairs_id: 00000000-0000-0000-0000-000000000000, session_id: fc1083d9-3e52-49b1-b95f-0bf05740a9d9, gen: 1 } (ConnectionId(19)) was previously active, clearing","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:48.711526033Z","hostname":"jepsen-n2","pid":609}
{"msg":"got message for disconnected id ConnectionId(19); ignoring","v":0,"name":"crucible","level":40,"time":"2025-10-21T15:38:48.711534841Z","hostname":"jepsen-n2","pid":609}
{"msg":"got message for disconnected id ConnectionId(19); ignoring","v":0,"name":"crucible","level":40,"time":"2025-10-21T15:38:48.711542786Z","hostname":"jepsen-n2","pid":609}
{"msg":"got message for disconnected id ConnectionId(19); ignoring","v":0,"name":"crucible","level":40,"time":"2025-10-21T15:38:48.711550872Z","hostname":"jepsen-n2","pid":609}
{"msg":"request completed","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:48.71155985Z","hostname":"jepsen-n2","pid":609,"uri":"/extent/0/repair-ready","method":"GET","req_id":"ffb5fdbb-31a0-46b2-9653-1b004686b4f4","remote_addr":"127.0.0.1:46705","local_addr":"0.0.0.0:7810","task":"repair","latency_us":15000733,"response_code":200}
{"msg":"got cancelled token; recv_task stopping","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:48.711583126Z","hostname":"jepsen-n2","pid":609,"task":"recv","id":"19"}
{"msg":"accepted connection from 172.21.252.194:49280","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:58.714490481Z","hostname":"jepsen-n2","pid":609,"task":"main"}
{"msg":"connection (172.21.252.194:49280): tasks spawned","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:58.714579978Z","hostname":"jepsen-n2","pid":609,"id":"20"}
{"msg":"Connection request from 00000000-0000-0000-0000-000000000000 with version 13","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:58.714591Z","hostname":"jepsen-n2","pid":609}
{"msg":"upstairs UpstairsConnection { upstairs_id: 00000000-0000-0000-0000-000000000000, session_id: fc1083d9-3e52-49b1-b95f-0bf05740a9d9, gen: 1 } connected, version 13","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:58.714600769Z","hostname":"jepsen-n2","pid":609}
{"msg":"UpstairsConnection { upstairs_id: 00000000-0000-0000-0000-000000000000, session_id: fc1083d9-3e52-49b1-b95f-0bf05740a9d9, gen: 1 } is now active (read-write)","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:58.718931355Z","hostname":"jepsen-n2","pid":609}
{"msg":"Current flush_numbers [0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:38:58.719801091Z","hostname":"jepsen-n2","pid":609}
{"msg":"21380 job ELiveReopen waiting on 1 deps","v":0,"name":"crucible","level":40,"time":"2025-10-21T15:39:03.725012067Z","hostname":"jepsen-n2","pid":609,"role":"work","upstairs_id":"00000000-0000-0000-0000-000000000000"}
{"msg":"21381 job Write waiting on 1 deps","v":0,"name":"crucible","level":40,"time":"2025-10-21T15:39:03.725138197Z","hostname":"jepsen-n2","pid":609,"role":"work","upstairs_id":"00000000-0000-0000-0000-000000000000"}
{"msg":"21382 job Read waiting on 1 deps","v":0,"name":"crucible","level":40,"time":"2025-10-21T15:39:03.725154419Z","hostname":"jepsen-n2","pid":609,"role":"work","upstairs_id":"00000000-0000-0000-0000-000000000000"}
{"msg":"Created copy dir \"/opt/crucible/data/00/000/000.copy\"","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:39:03.725550435Z","hostname":"jepsen-n2","pid":609}
{"msg":"accepted connection","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:39:03.725987603Z","hostname":"jepsen-n2","pid":609,"local_addr":"0.0.0.0:7810","task":"repair","remote_addr":"127.0.0.1:53922"}
{"msg":"request completed","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:39:03.726135917Z","hostname":"jepsen-n2","pid":609,"uri":"/extent/0/files","method":"GET","req_id":"323a34f4-7cde-4cac-a4da-61a68895f1fc","remote_addr":"127.0.0.1:53922","local_addr":"0.0.0.0:7810","task":"repair","latency_us":99,"response_code":200}
{"msg":"eid:0 Found repair files: [\"000\"]","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:39:03.726163141Z","hostname":"jepsen-n2","pid":609}
{"msg":"request completed","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:39:03.726510972Z","hostname":"jepsen-n2","pid":609,"uri":"/newextent/0/data","method":"GET","req_id":"867acd77-a7d9-4de6-bfef-06dbfd75a245","remote_addr":"127.0.0.1:53922","local_addr":"0.0.0.0:7810","task":"repair","latency_us":148,"response_code":200}
{"msg":"Verify extent 0 still ready for copy","v":0,"name":"crucible","level":30,"time":"2025-10-21T15:39:03.731080331Z","hostname":"jepsen-n2","pid":609}

[JustinAzoff]

The issue here was that running a downstairs with the default arguments causes a listen address of 0.0.0.0 to be used. this address is then passed around as the address to use for repair. This was causing this error on the upstairs:

{"msg":"job id 8922 saw error RepairRequestError(\"Failed to verify extent is still valid for repair Communication Error: error sending request for url (http://0.0.0.0:7810/extent/0/repair-ready)\")","v":0,"name":"crucible","level":50,"time":"2025-10-21T16:25:25.762998245Z","hostname":"jepsen-n4","pid":5785,"client":"0","":"downstairs","session_id":"e19f37bb-1da7-4ac1-8dd2-cc04a57aa240"}

Reconfiguring things so that the downstairs are all started with --address specified fixed the repair issue