500 error with local storage create: expected volblocksize to be 131072, but saw 16777216

[askfongjojo]

The instance failed to start even after waiting for some time.

              event time | sub saga | node id                                     | event type    | data
------------------------ | -------- | ------------------------------------------- | ------------- | ---
2026-03-28T21:25:49.725Z |          |                                   24: start | started       | 
2026-03-28T21:25:49.730Z |          |                                   24: start | succeeded     | 
2026-03-28T21:25:49.733Z |          |      0: instance_start.generate_propolis_id | started       | 
2026-03-28T21:25:49.736Z |          |      0: instance_start.generate_propolis_id | succeeded     | "propolis_id" => "222a584f-b759-4100-8909-df16d814b04c"
2026-03-28T21:25:49.739Z |          |              1: instance_start.alloc_server | started       | 
2026-03-28T21:25:49.776Z |          |              1: instance_start.alloc_server | succeeded     | "sled_id" => "e5909903-3a6c-4491-9046-bec3936bf8d0"
2026-03-28T21:25:49.779Z |          |         2: instance_start.alloc_propolis_ip | started       | 
2026-03-28T21:25:49.789Z |          |         2: instance_start.alloc_propolis_ip | succeeded     | "propolis_ip" => "fd4d:998:65fa:101::1:3"
2026-03-28T21:25:49.793Z |          |         3: instance_start.create_vmm_record | started       | 
2026-03-28T21:25:49.853Z |          |         3: instance_start.create_vmm_record | succeeded     | "vmm_record" => {"cpu_platform":"AmdMilan","gen":1,"id":"222a584f-b759-4100-8909-df16d814b04c","instance_id":"59743ead-3b78-4591-abf9-b3db422c9a6d","propolis_ip":"fd4d:998:65fa:101::1:3/128","propolis_port":12400,"sled_id":"e5909903-3a6c-4491-9046-bec3936bf8d0","state":"Creating","time_created":"2026-03-28T21:25:49.806232Z","time_deleted":null,"time_state_updated":"2026-03-28T21:25:49.806232Z"}
2026-03-28T21:25:49.857Z |          |          4: instance_start.mark_as_starting | started       | 
2026-03-28T21:25:49.916Z |          |          4: instance_start.mark_as_starting | succeeded     | "started_record" => {"auto_restart":{"cooldown":null,"policy":null},"boot_disk_id":null,"cpu_platform":null,"dst_propolis_id":null,"hostname":"primary","identity":{"description":"mongodb cluster","id":"59743ead-3b78-4591-abf9-b3db422c9a6d","name":"mongodb-ext4-bs512-primary","time_created":"2026-03-28T21:13:18.763282Z","time_deleted":null,"time_modified":"2026-03-28T21:13:18.763282Z"},"intended_state":"Running","memory":8589934592,"migration_id":null,"ncpus":4,"nexus_state":"Vmm","project_id":"1c62e171-5e3d-4606-9906-4fe46d0789e3","propolis_id":"222a584f-b759-4100-8909-df16d814b04c","state_generation":5,"time_last_auto_restarted":null,"time_state_updated":"2026-03-28T21:13:18.763282Z","updater_gen":1,"updater_id":null,"user_data":[35,99,108,111,117,100,45,99,111,110,102,105,103,10,109,97,110,97,103,101,95,101,116,99,95,104,111,115,116,115,58,32,116,114,117,101,10,115,115,104,95,32,112,119,97,117,116,104,58,32,49,10,99,104,112,97,115,115,119,100,58,10,32,32,108,105,115,116,58,10,32,32,32,32,45,32,117,98,117,110,116,117,58,111,120,105,100,101,10,32,32,101,120,112,105,114,101,58,32,102,97,108,115,101,10,114,117,110,99,109,100,58,10,45,32,39,115,101,100,32,45,105,32,34,115,47,45,32,117,112,100,97,116,101,95,101,116,99,95,104,111,115,116,115,47,35,32,38,47,34,32,47,101,116,99,47,99,108,111,117,100,47,99,108,111,117,100,46,99,102,103,39,10,45,32,39,99,117,114,108,32,104,116,116,112,115,58,47,47,103,105,115,116,46,103,105,116,104,117,98,117,115,101,114,99,111,110,116,101,110,116,46,99,111,109,47,97,115,107,102,111,110,103,106,111,106,111,47,49,56,49,102,99,49,100,49,102,52,97,98,56,100,100,48,55,100,49,99,51,53,55,54,97,49,101,54,51,102,49,54,47,114,97,119,47,50,99,50,50,56,56,101,52,102,98,50,53,50,99,99,50,101,48,48,100,53,102,100,53,53,97,50,52,99,56,101,51,54,99,98,98,49,55,49,49,47,109,111,110,103,111,100,98,45,105,110,115,116,97,108,108,45,99,111,110,102,105,103,32,124,32,47,98,105,110,47,98,97,115,104,32,45,115,32,101,120,116,52,39,10,45,32,91,32,115,104,44,32,45,99,44,32,34,115,108,101,101,112,32,49,50,48,34,32,93,10,45,32,39,99,117,114,108,32,104,116,116,112,115,58,47,47,103,105,115,116,46,103,105,116,104,117,98,117,115,101,114,99,111,110,116,101,110,116,46,99,111,109,47,97,115,107,102,111,110,103,106,111,106,111,47,49,56,49,102,99,49,100,49,102,52,97,98,56,100,100,48,55,100,49,99,51,53,55,54,97,49,101,54,51,102,49,54,47,114,97,119,47,50,99,50,50,56,56,101,52,102,98,50,53,50,99,99,50,101,48,48,100,53,102,100,53,53,97,50,52,99,56,101,51,54,99,98,98,49,55,49,49,47,109,111,110,103,111,100,98,45,99,114,101,97,116,101,45,99,108,117,115,116,101,114,32,124,32,47,98,105,110,47,98,97,115,104,32,45,115,32,104,116,116,112,115,58,47,47,114,101,99,111,118,101,114,121,46,115,121,115,46,109,97,100,114,105,100,46,101,110,103,46,111,120,105,100,101,46,99,111,109,112,117,116,101,114,32,111,120,105,100,101,45,116,111,107,101,110,45,48,55,48,48,100,102,53,98,49,49,98,99,52,57,101,54,55,53,101,49,55,101,51,53,55,99,49,53,57,48,100,97,52,54,100,57,99,54,56,51,32,101,120,116,52,32,53,49,50,32,97,110,103,101,108,97,39,10,45,32,101,99,104,111,32,39,42,42,42,42,42,42,42,42,42,42,32,99,117,115,116,111,109,32,115,101,116,117,112,32,99,111,109,112,108,101,116,101,100,32,42,42,42,42,42,42,42,42,42,42,39,10]}
2026-03-28T21:25:49.920Z |          |        5: instance_start.list_local_storage | started       | 
2026-03-28T21:25:49.975Z |          |        5: instance_start.list_local_storage | succeeded     | "local_storage_records" => [{"disk":{"attach_instance_id":"59743ead-3b78-4591-abf9-b3db422c9a6d","block_size":"AdvancedFormat","disk_state":"attached","disk_type":"LocalStorage","identity":{"description":"empty volume for data","id":"617d0622-109d-41ec-912f-476137be2834","name":"dbdata-ext4-bs512-primary","time_created":"2026-03-28T21:13:09.112678Z","time_deleted":null,"time_modified":"2026-03-28T21:13:09.112678Z"},"project_id":"1c62e171-5e3d-4606-9906-4fe46d0789e3","rcgen":1,"size":85899345920,"slot":1,"state_generation":2,"time_state_updated":"2026-03-28T21:13:09.240129Z"},"disk_type_local_storage":{"disk_id":"617d0622-109d-41ec-912f-476137be2834","local_storage_dataset_allocation_id":null,"local_storage_unencrypted_dataset_allocation_id":"08dfe09d-7441-43e7-8512-bb64286a3960","required_dataset_overhead":5872025600},"local_storage_dataset_allocation":{"Unencrypted":{"dataset_size":91771371520,"id":"08dfe09d-7441-43e7-8512-bb64286a3960","local_storage_unencrypted_dataset_id":"6e909d78-eb59-4d59-93dd-67540c12ce18","pool_id":"8d0997df-bdb7-462d-a368-4d2e37edd973","sled_id":"e5909903-3a6c-4491-9046-bec3936bf8d0","time_created":"2026-03-28T21:13:20.422324Z","time_deleted":null}}}]
2026-03-28T21:25:49.979Z |          |    8: instance_start.ensure_local_storage_2 | started       | 
2026-03-28T21:25:49.982Z |          |  17: instance_start.ensure_local_storage_11 | started       | 
2026-03-28T21:25:49.986Z |          |    8: instance_start.ensure_local_storage_2 | succeeded     | 
2026-03-28T21:25:49.988Z |          |  17: instance_start.ensure_local_storage_11 | succeeded     | 
2026-03-28T21:25:49.991Z |          |   15: instance_start.ensure_local_storage_9 | started       | 
2026-03-28T21:25:49.994Z |          |  16: instance_start.ensure_local_storage_10 | started       | 
2026-03-28T21:25:49.998Z |          |   15: instance_start.ensure_local_storage_9 | succeeded     | 
2026-03-28T21:25:50.001Z |          |  16: instance_start.ensure_local_storage_10 | succeeded     | 
2026-03-28T21:25:50.003Z |          |   14: instance_start.ensure_local_storage_8 | started       | 
2026-03-28T21:25:50.006Z |          |   13: instance_start.ensure_local_storage_7 | started       | 
2026-03-28T21:25:50.010Z |          |   14: instance_start.ensure_local_storage_8 | succeeded     | 
2026-03-28T21:25:50.012Z |          |   13: instance_start.ensure_local_storage_7 | succeeded     | 
2026-03-28T21:25:50.015Z |          |   12: instance_start.ensure_local_storage_6 | started       | 
2026-03-28T21:25:50.018Z |          |   11: instance_start.ensure_local_storage_5 | started       | 
2026-03-28T21:25:50.020Z |          |   12: instance_start.ensure_local_storage_6 | succeeded     | 
2026-03-28T21:25:50.023Z |          |   11: instance_start.ensure_local_storage_5 | succeeded     | 
2026-03-28T21:25:50.026Z |          |   10: instance_start.ensure_local_storage_4 | started       | 
2026-03-28T21:25:50.029Z |          |    9: instance_start.ensure_local_storage_3 | started       | 
2026-03-28T21:25:50.031Z |          |   10: instance_start.ensure_local_storage_4 | succeeded     | 
2026-03-28T21:25:50.034Z |          |    9: instance_start.ensure_local_storage_3 | succeeded     | 
2026-03-28T21:25:50.037Z |          |    7: instance_start.ensure_local_storage_1 | started       | 
2026-03-28T21:25:50.040Z |          |    6: instance_start.ensure_local_storage_0 | started       | 
2026-03-28T21:25:50.043Z |          |    7: instance_start.ensure_local_storage_1 | succeeded     | 
2026-03-28T21:25:50.127Z |          |    6: instance_start.ensure_local_storage_0 | failed        | "ensure_local_storage_0" => {"ActionFailed":{"source_error":{"InternalError":{"internal_message":"failed to ensure local storage: failed at attempt 1: progenitor API operation failed: Error Response: status: 500 Internal Server Error; headers: {\"content-type\": \"application/json\", \"x-request-id\": \"fee70047-ce8d-46fb-bbd3-28aaf257de7e\", \"content-length\": \"124\", \"date\": \"Sat, 28 Mar 2026 21:25:50 GMT\"}; value: Error { error_code: Some(\"Internal\"), message: \"Internal Server Error\", request_id: \"fee70047-ce8d-46fb-bbd3-28aaf257de7e\" }"}}}}

Checked the actual error in sled-agent and it turned out to be unrelated to timing:

21:35:11.273Z INFO SledAgent (dropshot (SledAgent)): request completed
    error_message_external = Internal Server Error
    error_message_internal = Failed to ensure volume 'oxp_d5ecbab3-d076-48d1-931d-58003120190a/local_storage_unencrypted/490b5f86-496f-4b4f-a390-89dbbbf1c9bc/vol': expected volblocksize to be 131072, but saw 16777216
    file = /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.7/src/server.rs:855
    latency_us = 67000
    local_addr = [fd4d:998:65fa:104::1]:12345
    method = POST
    remote_addr = [fd4d:998:65fa:103::4]:47537
    req_id = 70d9236d-aec6-47da-ac8d-6b618b19f52a
    response_code = 500
    uri = /local-storage

[askfongjojo]

This is on madrid, running a commit from 3/27:

root@oxz_switch0:~# pilot host ls
CUBBY IP                        SERIAL      IMAGE
14    fe80::aa40:25ff:fe04:3d2  BRM42220081 ci 74b7742/18e26f9 2026-03-27 22:17
15    fe80::aa40:25ff:fe04:396  BRM42220046 ci 74b7742/18e26f9 2026-03-27 22:17
16    fe80::aa40:25ff:fe04:2d7  BRM42220007 ci 74b7742/18e26f9 2026-03-27 22:17
17    fe80::aa40:25ff:fe04:157  BRM42220004 ci 74b7742/18e26f9 2026-03-27 22:17

[askfongjojo]

Hmm, something seems wrong with rkadm - it might not have updated everything correctly (I discovered this when setting the target release to the TUF repo didn't complete and I noticed the SP versions were old). I'm double-checking by mupdating the sleds via wicket all over.

[askfongjojo]

A full mupdate didn't change anything (for both the existing local disk that failed to be created and a new one made after mupdate). I'll clean-slate the lab and retry, once I can get a hold of it again.

Latest: Same error with a clean slate install on london (saga_id: 5bfbf93e-c289-4bac-8c8d-57634d5f1255).

root@oxz_switch0:~# pilot host exec -c 'grep volblocksize /var/svc/log/oxide-sled-agent*' 14-17
14  BRM42220036        ok: {"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2026-03-30T06:10:02.73223244Z","hostname":"BRM42220036","pid":10686,"uri":"/local-storage","method":"POST","req_id":"5bc72623-48af-4966-bc73-5955a68bc20b","remote_addr":"[fd65:62a2:a81b:102::5]:38091","local_addr":"[fd65:62a2:a81b:101::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.7/src/server.rs:855","error_message_external":"Internal Server Error","error_message_internal":"Failed to ensure volume 'oxp_4c58b341-519b-41b2-a280-663e18c237d8/local_storage_unencrypted/636152f1-2339-453d-b112-51f1071ea2d5/vol': expected volblocksize to be 131072, but saw 16777216","latency_us":558579,"response_code":500}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2026-03-30T06:10:26.881851616Z","hostname":"BRM42220036","pid":10686,"uri":"/local-storage","method":"POST","req_id":"d1f3e6b2-7788-4e81-8563-273d48449389","remote_addr":"[fd65:62a2:a81b:102::5]:50214","local_addr":"[fd65:62a2:a81b:101::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.7/src/server.rs:855","error_message_external":"Internal Server Error","error_message_internal":"Failed to ensure volume 'oxp_4c58b341-519b-41b2-a280-663e18c237d8/local_storage_unencrypted/636152f1-2339-453d-b112-51f1071ea2d5/vol': expected volblocksize to be 131072, but saw 16777216","latency_us":66174,"response_code":500}
...

[jmpesp]

This is almost certainly related to the integration of optimized record size allocation for raw zvols. I'll change the sled-agent to not attempt to ensure something different here.