crucible zone running out of space earlier than the control plane "thinks"

[askfongjojo]

The problem crucible dataset is on rack2, in cubby 9. First, It hit an "out of space" error when it attempted to recreate one of the datasets:

BRM44220005 # zlogin oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1
[Connected to zone 'oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1' pts/5]
Last login: Fri Oct  6 04:06:28 on pts/5
The illumos Project     helios-2.0.22216        October 2023
root@oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1:~# netstat -an | grep 32345
root@oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1:~# svcs *agent*
STATE          STIME    FMRI
online          4:10:47 svc:/oxide/crucible/agent:default

In /pool/ext/d1cb6b7d-2b92-4b7d-8a4d-551987f0277e/crypt/debug/oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/oxide-crucible-agent:default.log.1696555801, I saw that a new region child dataset failed to be created:

23:50:35.650Z INFO crucible-agent (dropshot): accepted connection
    local_addr = [fd00:1122:3344:105::e]:32345
    remote_addr = [fd00:1122:3344:103::3]:65223
23:50:35.712Z INFO crucible-agent (datafile): region b8f6b08b-e74b-47c2-b2e8-48463f798e68 state: Requested
23:50:35.730Z INFO crucible-agent (dropshot): request completed
    latency_us = 37941
    local_addr = [fd00:1122:3344:105::e]:32345
    method = POST
    remote_addr = [fd00:1122:3344:103::3]:65223
    req_id = 42d49808-af5f-44d5-8065-1381aeeec6f5
    response_code = 200
    uri = /crucible/0/regions
23:50:35.735Z INFO crucible-agent (worker): Region size:107374182400 reservation:134217728000 quota:322122547200
23:50:35.758Z INFO crucible-agent (worker): zfs set reservation of 134217728000 for oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/b8f6b08b-e74b-47c2-b2e8-48463f798e68
23:50:35.758Z INFO crucible-agent (worker): zfs set quota of 322122547200 for oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/b8f6b08b-e74b-47c2-b2e8-48463f798e68
23:50:35.855Z INFO crucible-agent (worker): creating region Region { id: RegionId("b8f6b08b-e74b-47c2-b2e8-48463f798e68"), state: Requested, block_size: 512, extent_size: 131072, extent_count: 1600, encrypted: true, port_number: 19007, cert_pem: None, key_pem: None, root_pem: None } at "/data/regions/b8f6b08b-e74b-47c2-b2e8-48463f798e68"
    region = b8f6b08b-e74b-47c2-b2e8-48463f798e68
23:50:36.036Z INFO crucible-agent (dropshot): request completed
    latency_us = 95
    local_addr = [fd00:1122:3344:105::e]:32345
    method = POST
    remote_addr = [fd00:1122:3344:103::3]:65223
    req_id = ef526616-e9dd-43ca-8d03-b1df49d9f8fa
    response_code = 200
    uri = /crucible/0/regions
23:50:36.389Z INFO crucible-agent (dropshot): request completed
    latency_us = 64
    local_addr = [fd00:1122:3344:105::e]:32345
    method = POST
    remote_addr = [fd00:1122:3344:103::3]:65223
    req_id = 7da47c3b-7045-4c55-ae19-3bf20ccbccfc
    response_code = 200
    uri = /crucible/0/regions
23:50:36.924Z INFO crucible-agent (dropshot): request completed
    latency_us = 114
    local_addr = [fd00:1122:3344:105::e]:32345
    method = POST
    remote_addr = [fd00:1122:3344:103::3]:65223
    req_id = 08ef81ec-a3d3-4fa5-9b2c-8e607171e774
    response_code = 200
    uri = /crucible/0/regions
23:50:37.205Z INFO crucible-agent (worker): region files created ok
    region = b8f6b08b-e74b-47c2-b2e8-48463f798e68
23:50:37.205Z INFO crucible-agent (datafile): region b8f6b08b-e74b-47c2-b2e8-48463f798e68 state: Requested -> Created
23:50:37.206Z INFO crucible-agent (worker): applying SMF actions post create...
23:50:37.253Z INFO crucible-agent (worker): creating missing downstairs instance downstairs-b8f6b08b-e74b-47c2-b2e8-48463f798e68
23:50:37.264Z INFO crucible-agent (worker): ok, have svc:/oxide/crucible/downstairs:downstairs-b8f6b08b-e74b-47c2-b2e8-48463f798e68
23:50:37.272Z INFO crucible-agent (worker): creating config property group
23:50:37.273Z INFO crucible-agent (worker): reconfiguring svc:/oxide/crucible/downstairs:downstairs-b8f6b08b-e74b-47c2-b2e8-48463f798e68
23:50:37.274Z INFO crucible-agent (worker): ensure directory SCF_TYPE_ASTRING /data/regions/b8f6b08b-e74b-47c2-b2e8-48463f798e68
23:50:37.274Z INFO crucible-agent (worker): ensure port SCF_TYPE_COUNT 19007
23:50:37.274Z INFO crucible-agent (worker): ensure address SCF_TYPE_ASTRING fd00:1122:3344:105::e
23:50:37.274Z INFO crucible-agent (worker): commit
23:50:37.276Z INFO crucible-agent (worker): ok!
23:50:37.297Z INFO crucible-agent (worker): SMF ok!
23:50:39.451Z INFO crucible-agent (dropshot): request completed
    latency_us = 125
    local_addr = [fd00:1122:3344:105::e]:32345
    method = POST
    remote_addr = [fd00:1122:3344:103::3]:65223
    req_id = 6aac231f-be8f-437f-bc6d-358c9d12b282
    response_code = 200
    uri = /crucible/0/regions
23:51:21.113Z INFO crucible-agent (dropshot): accepted connection
    local_addr = [fd00:1122:3344:105::e]:32345
    remote_addr = [fd00:1122:3344:103::3]:55939
23:51:21.113Z INFO crucible-agent (datafile): region d9968d58-5e4f-4349-aaf9-f88024ebf8b4 state: Requested
23:51:21.113Z INFO crucible-agent (worker): Region size:107374182400 reservation:134217728000 quota:322122547200
23:51:21.113Z INFO crucible-agent (dropshot): request completed
    latency_us = 418
    local_addr = [fd00:1122:3344:105::e]:32345
    method = POST
    remote_addr = [fd00:1122:3344:103::3]:55939
    req_id = 399b0741-53b1-4afd-bf65-bb40a0ae37ec
    response_code = 200
    uri = /crucible/0/regions
23:51:21.130Z INFO crucible-agent (worker): zfs set reservation of 134217728000 for oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/d9968d58-5e4f-4349-aaf9-f88024ebf8b4
23:51:21.130Z INFO crucible-agent (worker): zfs set quota of 322122547200 for oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/d9968d58-5e4f-4349-aaf9-f88024ebf8b4
thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: zfs create failed! out: err:cannot create 'oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/d9968d58-5e4f-4349-aaf9-f88024ebf8b4': out of space
', agent/src/main.rs:1584:30
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[ Oct  5 23:51:21 Stopping because service exited with an error. ]
...

Subsequent retries failed with out of space error until 2023-10-05T23:51:43.014916396Z. After that, the error turned into "Dataset does not exist!":

{"msg":"request completed","v":0,"name":"crucible-agent","level":30,"time":"2023-10-05T23:51:43.014916396Z","hostname":"oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1","pid":21624,"uri
":"/crucible/0/regions/d9968d58-5e4f-4349-aaf9-f88024ebf8b4","method":"GET","req_id":"1cf1e37c-5a99-460f-a8be-f9582b240cf5","remote_addr":"[fd00:1122:3344:103::3]:45987","local_addr":"[fd
00:1122:3344:105::e]:32345","component":"dropshot","latency_us":92,"response_code":"200"}
thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: zfs create failed! out: err:cannot create 'oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/d9968d58-
5e4f-4349-aaf9-f88024ebf8b4': out of space
', agent/src/main.rs:1584:30
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[ Oct  5 23:51:43 Stopping because service exited with an error. ]
[ Oct  5 23:51:43 Failing too quickly, throttling. ]
[ Oct  5 23:51:44 Executing start method ("/opt/oxide/lib/svc/manifest/crucible/agent.sh"). ]
+ . /lib/svc/share/smf_include.sh
++ SMF_EXIT_OK=0
++ SMF_EXIT_NODAEMON=94
++ SMF_EXIT_ERR_FATAL=95
++ SMF_EXIT_ERR_CONFIG=96
++ SMF_EXIT_MON_DEGRADE=97
++ SMF_EXIT_MON_OFFLINE=98
++ SMF_EXIT_ERR_NOSMF=99
++ SMF_EXIT_ERR_PERM=100
++ svcprop -c -p config/datalink svc:/oxide/crucible/agent:default
+ DATALINK=oxControlService2
++ svcprop -c -p config/gateway svc:/oxide/crucible/agent:default
+ GATEWAY=fd00:1122:3344:105::1
++ svcprop -c -p config/dataset svc:/oxide/crucible/agent:default
+ DATASET=oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible
++ svcprop -c -p config/listen_addr svc:/oxide/crucible/agent:default
+ LISTEN_ADDR=fd00:1122:3344:105::e
++ svcprop -c -p config/listen_port svc:/oxide/crucible/agent:default
+ LISTEN_PORT=32345
++ svcprop -c -p config/portbase svc:/oxide/crucible/agent:default
+ PORTBASE=19000
++ svcprop -c -p config/downstairs_prefix svc:/oxide/crucible/agent:default
+ DOWNSTAIRS_PREFIX=downstairs
++ svcprop -c -p config/snapshot_prefix svc:/oxide/crucible/agent:default
+ SNAPSHOT_PREFIX=snapshot
+ [[ oxControlService2 == unknown ]]
+ [[ fd00:1122:3344:105::1 == unknown ]]
+ ipadm delete-if oxControlService2
+ ipadm create-if -t oxControlService2
+ ipadm set-ifprop -t -p mtu=9000 -m ipv4 oxControlService2
+ ipadm set-ifprop -t -p mtu=9000 -m ipv6 oxControlService2
+ ipadm show-addr oxControlService2/ll
ipadm: Address object not found
+ ipadm create-addr -t -T addrconf oxControlService2/ll
+ ipadm show-addr oxControlService2/omicron6
ipadm: Address object not found
+ ipadm create-addr -t -T static -a fd00:1122:3344:105::e oxControlService2/omicron6
+ route get -inet6 default -inet6 fd00:1122:3344:105::1
   route to: default
destination: default
       mask: default
    gateway: fd00:1122:3344:105::1
  interface: oxControlService2
      flags: <UP,GATEWAY,DONE,STATIC>
 recvpipe  sendpipe  ssthresh    rtt,ms rttvar,ms  hopcount      mtu     expire
       0         0         0         0         0         0      9000         0 
+ args=('-D' '/opt/oxide/crucible/bin/crucible-downstairs' '--dataset' "$DATASET" '-l' "[$LISTEN_ADDR]:$LISTEN_PORT" '-P' "$PORTBASE" '-p' "$DOWNSTAIRS_PREFIX" '-s' "$SNAPSHOT_PREFIX")
+ exec /opt/oxide/crucible/bin/crucible-agent run -D /opt/oxide/crucible/bin/crucible-downstairs --dataset oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible -l '[fd00:1122:3344:105::e]:32345' -P 19000 -p downstairs -s snapshot
note: configured to log to "/dev/stdout"
{"msg":"dataset: \"oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible\"","v":0,"name":"crucible-agent","level":30,"time":"2023-10-05T23:51:44.62572869Z","hostname":"oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1","pid":21648}
{"msg":"listen IP: [fd00:1122:3344:105::e]:32345","v":0,"name":"crucible-agent","level":30,"time":"2023-10-05T23:51:44.633081464Z","hostname":"oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1","pid":21648}
{"msg":"SMF instance name downstairs_prefix: \"downstairs\"","v":0,"name":"crucible-agent","level":30,"time":"2023-10-05T23:51:44.633091172Z","hostname":"oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1","pid":21648}
{"msg":"applying SMF actions before removal...","v":0,"name":"crucible-agent","level":30,"time":"2023-10-05T23:51:44.70104607Z","hostname":"oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1","pid":21648,"component":"worker"}
{"msg":"listening","v":0,"name":"crucible-agent","level":30,"time":"2023-10-05T23:51:44.70888773Z","hostname":"oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1","pid":21648,"local_addr":"[fd00:1122:3344:105::e]:32345","component":"dropshot"}
{"msg":"SMF ok!","v":0,"name":"crucible-agent","level":30,"time":"2023-10-05T23:51:44.727007026Z","hostname":"oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1","pid":21648,"component":"worker"}
thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: Dataset does not exist!', agent/src/main.rs:1647:30
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[ Oct  5 23:51:44 Stopping because service exited with an error. ]

But the dataset and mountpoint seemed to already exist and I was able to list the files under it:

root@oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1:~# mount
/ on oxp_b358fb1e-f52a-4a63-9aab-170225509b37/crypt/zone/oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1 read/write/setuid/devices/nonbmand/exec/xattr/atime/dev=2a90032 on Thu Oct  5 17:20:50 2023
/dev on /dev read/write/setuid/devices/dev=80c000b on Thu Oct  5 17:21:16 2023
/system/lib on /system/lib read only/setuid/nodevices/nosub/dev=2a90002 on Thu Oct  5 17:21:16 2023
/system/sbin on /system/sbin read only/setuid/nodevices/nosub/dev=2a90002 on Thu Oct  5 17:21:16 2023
/system/usr on /system/usr read only/setuid/nodevices/nosub/dev=2a90002 on Thu Oct  5 17:21:16 2023
/proc on proc read/write/setuid/nodevices/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=814000b on Thu Oct  5 17:21:16 2023
/system/contract on ctfs read/write/setuid/nodevices/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=81c000c on Thu Oct  5 17:21:16 2023
/etc/mnttab on mnttab read/write/setuid/nodevices/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=820000c on Thu Oct  5 17:21:16 2023
/system/object on objfs read/write/setuid/nodevices/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=828000c on Thu Oct  5 17:21:16 2023
/etc/svc/volatile on swap read/write/setuid/nodevices/xattr/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=8240010 on Thu Oct  5 17:21:16 2023
/etc/dfs/sharetab on sharefs read/write/setuid/nodevices/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=830000c on Thu Oct  5 17:21:16 2023
/system/lib/libc.so.1 on /usr/lib/libc/libc_hwcap2.so.1 read/write/setuid/devices/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a90002 on Thu Oct  5 17:21:18 2023
/dev/fd on fd read/write/setuid/nodevices/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=83c000c on Thu Oct  5 17:21:18 2023
/tmp on swap read/write/setuid/nodevices/xattr/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=8240025 on Thu Oct  5 17:21:18 2023
/var/run on swap read/write/setuid/nodevices/xattr/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=8240026 on Thu Oct  5 17:21:18 2023
/data on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a90082 on Thu Oct  5 17:21:25 2023
/data/regions on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a90083 on Thu Oct  5 17:21:25 2023
/data/regions/65c47fd3-d7e9-4766-9c6d-e741bda54486 on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/65c47fd3-d7e9-4766-9c6d-e741bda54486 read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a90084 on Thu Oct  5 17:21:25 2023
/data/regions/9c4e7e66-d70c-4a28-a47c-7a4e695ae237 on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/9c4e7e66-d70c-4a28-a47c-7a4e695ae237 read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a90086 on Thu Oct  5 17:21:25 2023
/data/regions/a0e9d315-1787-4c87-b0ed-7d589c76eb06 on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/a0e9d315-1787-4c87-b0ed-7d589c76eb06 read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a90087 on Thu Oct  5 17:21:25 2023
/data/regions/d121c918-7a4d-4839-9b2f-c0169d5e423e on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/d121c918-7a4d-4839-9b2f-c0169d5e423e read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a90088 on Thu Oct  5 17:21:25 2023
/data/regions/f49d1dfe-cd14-406a-bf1d-93919cdee59d on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/f49d1dfe-cd14-406a-bf1d-93919cdee59d read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a90085 on Thu Oct  5 17:21:25 2023
/data/regions/65b01b8d-ccbf-4dbb-adf9-14eb5d41eeb0 on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/65b01b8d-ccbf-4dbb-adf9-14eb5d41eeb0 read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a90089 on Thu Oct  5 17:21:25 2023
/data/regions/cb4839f3-8f75-4f94-afca-4952e4b623ff on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/cb4839f3-8f75-4f94-afca-4952e4b623ff read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a9008a on Thu Oct  5 17:21:25 2023
/data/regions/ae1e3f13-bbd4-44a9-ad31-4a9f0e390291 on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/ae1e3f13-bbd4-44a9-ad31-4a9f0e390291 read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a9008b on Thu Oct  5 17:21:25 2023
/data/regions/a5c85269-bf1f-415f-a3aa-036d5507339d on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/a5c85269-bf1f-415f-a3aa-036d5507339d read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a9008c on Thu Oct  5 17:21:25 2023
/data/regions/f2fc3c4e-7563-4e62-8092-e8f81bc403f7 on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/f2fc3c4e-7563-4e62-8092-e8f81bc403f7 read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a9008d on Thu Oct  5 17:21:25 2023
/data/regions/b8f6b08b-e74b-47c2-b2e8-48463f798e68 on oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/b8f6b08b-e74b-47c2-b2e8-48463f798e68 read/write/setuid/nodevices/nonbmand/exec/xattr/atime/zone=oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1/dev=2a9009f on Thu Oct  5 23:50:35 2023

root@oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1:~# zfs list -r
NAME                                                                                             USED  AVAIL     REFER  MOUNTPOINT
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5                                                        2.81T  10.2G       24K  /oxp_57650e05-36ff-4de8-865f-b9562bdb67f5
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible                                               2.81T  10.2G     46.5K  /data
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions                                       2.81T  10.2G       34K  /data/regions
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/65b01b8d-ccbf-4dbb-adf9-14eb5d41eeb0   610M  1010G      610M  /data/regions/65b01b8d-ccbf-4dbb-adf9-14eb5d41eeb0
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/65c47fd3-d7e9-4766-9c6d-e741bda54486  76.2M   135G     76.2M  /data/regions/65c47fd3-d7e9-4766-9c6d-e741bda54486
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/9c4e7e66-d70c-4a28-a47c-7a4e695ae237  9.52G  13.1G     9.52G  /data/regions/9c4e7e66-d70c-4a28-a47c-7a4e695ae237
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/a0e9d315-1787-4c87-b0ed-7d589c76eb06  60.0G  12.7G     60.0G  /data/regions/a0e9d315-1787-4c87-b0ed-7d589c76eb06
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/a5c85269-bf1f-415f-a3aa-036d5507339d  47.5G  42.7G     47.5G  /data/regions/a5c85269-bf1f-415f-a3aa-036d5507339d
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/ae1e3f13-bbd4-44a9-ad31-4a9f0e390291   611M  1010G      611M  /data/regions/ae1e3f13-bbd4-44a9-ad31-4a9f0e390291
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/b8f6b08b-e74b-47c2-b2e8-48463f798e68  8.68G   126G     8.68G  /data/regions/b8f6b08b-e74b-47c2-b2e8-48463f798e68
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/cb4839f3-8f75-4f94-afca-4952e4b623ff  6.44G   254G     6.44G  /data/regions/cb4839f3-8f75-4f94-afca-4952e4b623ff
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/d121c918-7a4d-4839-9b2f-c0169d5e423e   173M  22.5G      173M  /data/regions/d121c918-7a4d-4839-9b2f-c0169d5e423e
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/f2fc3c4e-7563-4e62-8092-e8f81bc403f7  76.2M   135G     76.2M  /data/regions/f2fc3c4e-7563-4e62-8092-e8f81bc403f7
oxp_57650e05-36ff-4de8-865f-b9562bdb67f5/crucible/regions/f49d1dfe-cd14-406a-bf1d-93919cdee59d  76.3G  13.9G     76.3G  /data/regions/f49d1dfe-cd14-406a-bf1d-93919cdee59d
root@oxz_crucible_23dca27d-c79b-4930-a817-392e8aeaa4c1:~# ls -ltr /data
total 27
drwxr-xr-x  13 root     root          13 Oct  5 23:50 regions
-rw-------   1 root     root       10494 Oct  6 03:23 crucible.json

[askfongjojo]

In /data/crucible.json, I saw this region with a tombstoned status:

    "f49d1dfe-cd14-406a-bf1d-93919cdee59d": {
      "id": "f49d1dfe-cd14-406a-bf1d-93919cdee59d",
      "state": "tombstoned",
      "block_size": 512,
      "extent_size": 131072,
      "extent_count": 1024,
      "encrypted": true,
      "port_number": 19005,
      "cert_pem": null,
      "key_pem": null,
      "root_pem": null
    }

This dataset is still taking up space according to zfs list. I'm not sure if this could be the issue.

This is the space that the control plane thinks is in use:

root@[fd00:1122:3344:105::3]:32221/omicron> select * from dataset where id = '23dca27d-c79b-4930-a817-392e8aeaa4c1';
                   id                  |         time_created          |         time_modified         | time_deleted | rcgen |               pool_id                |          ip           | port  |   kind   |  size_used
---------------------------------------+-------------------------------+-------------------------------+--------------+-------+--------------------------------------+-----------------------+-------+----------+---------------
  23dca27d-c79b-4930-a817-392e8aeaa4c1 | 2023-08-30 18:59:10.758512+00 | 2023-08-30 18:59:10.758512+00 | NULL         |     1 | 57650e05-36ff-4de8-865f-b9562bdb67f5 | fd00:1122:3344:105::e | 32345 | crucible | 642097610752
(1 row)

We know the control plane accounting won't match the physical space consumed but maybe it is off by too much in this case. The concern is that customers are going into run into this same problem soon.

[askfongjojo]

This duplicates oxidecomputer/crucible#861 but is more about how we can prevent the out-of-space situation. I've updated the bug description to indicate that.

[leftwo]

How does the control plane populate that "size_used" column on the dataset table?
Crucible reserves more space for the region than the user requests, and I bet we never told
the control plane about that.

[askfongjojo]

Here?

omicron/nexus/db-queries/src/db/queries/region_allocation.rs

Lines 482 to 519 in cf3bdae

	impl UpdateDatasets {
	fn new(
	do_insert: &DoInsert,
	proposed_dataset_changes: &ProposedChanges,
	) -> Self {
	use crate::db::schema::dataset::dsl as dataset_dsl;
	let datasets_with_updates = proposed_dataset_changes
	.query_source()
	.select(proposed_dataset_changes::columns::id)
	.into_boxed();
	Self {
	query: Box::new(
	diesel::update(
	dataset_dsl::dataset.filter(
	dataset_dsl::id.eq_any(datasets_with_updates)
	)
	)
	.filter(
	do_insert.query_source()
	.select(do_insert::insert)
	.single_value()
	.assume_not_null()
	)
	.set(
	dataset_dsl::size_used.eq(
	dataset_dsl::size_used + proposed_dataset_changes.query_source()
	.filter(proposed_dataset_changes::columns::id.eq(dataset_dsl::id))
	.select(proposed_dataset_changes::columns::size_used_delta)
	.single_value()
	)
	)
	.returning(crate::db::schema::dataset::all_columns)
	)
	}
	}
	}

[leftwo]

Yeah, that's where the update is. I'll (or someone) will have to walk that back to where nexus figures out what
size it is using for the dataset, then some way to have it use the same multiplier we use in crucible, keeping the
two in sync

[askfongjojo]

While attempting to get crucible agent back online, I realized that I missed digging deeper into why there were tomestoned regions. The "Dataset does not exist" error actually came from the same region/downstairs with the id d9968d58-5e4f-4349-aaf9-f88024ebf8b4 - the one that could not get created when the dataset was out of space. The disk state was turned into faulted after reaching some timeout and the region was eventually tomestoned:

root@[fd00:1122:3344:105::3]:32221/omicron> select id, name, disk_state, volume_id, time_created, time_deleted from disk where volume_id in (select volume_id from region
where id = 'd9968d58-5e4f-4349-aaf9-f88024ebf8b4');
                   id                  |       name        | disk_state |              volume_id               |         time_created          | time_deleted
---------------------------------------+-------------------+------------+--------------------------------------+-------------------------------+---------------
  993a2f7a-8bcf-4be5-ae2b-5ca1bfbf250c | sb-mysql-4c16g-12 | faulted    | 9aeaf7e8-c7dc-4a3e-8db5-47099c36acef | 2023-10-05 23:51:20.837965+00 | NULL

23:51:42.956Z INFO crucible-agent (datafile): region d9968d58-5e4f-4349-aaf9-f88024ebf8b4 state: Requested -> Tombstoned

Normally upon the start of crucible agent SMF service, it destroys the tombstoned regions and cleans up all the artifacts. But the above downstairs was stuck in a situation that could never be cleaned up. The agent kept trying in vain to delete a region that didn't get created in the first place. We may need to teach crucible how to handle this situation though the root cause is still about control plane not understanding the real capacity.

The situation was made worse when crucible agent panicked and running sagas ended up creating a region in crucible while CRDB considered it gone. There are 3 such orphan regions in that crucible zone that did not have volume and region records because of the failed disk_create saga. Here is an example (region id: 65b01b8d-ccbf-4dbb-adf9-14eb5d41eeb0)

root@[fd00:1122:3344:105::3]:32221/omicron> select event_type,data from saga_node_event where saga_id = '59466dd9-aa07-4948-a95c-aab6de6e705f';
   event_type   |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               data
----------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  started       | NULL
  succeeded     | "b97593f4-616c-442c-999b-5210da2eab57"
  undo_finished | NULL
  undo_started  | NULL
  started       | NULL
  succeeded     | "cb68ad8a-64ab-4ce6-bede-b60ddef9aed5"
  undo_finished | NULL
  undo_started  | NULL
  started       | NULL
  succeeded     | {"block_size": "Traditional", "create_image_id": "cb6eb1e9-69fd-40ad-9373-83926f8b32d9", "create_snapshot_id": null, "identity": {"description": "cb6eb1e9-69fd-40ad-9373-83926f8b32d9 test instance ", "id": "b97593f4-616c-442c-999b-5210da2eab57", "name": "one-each-32c-128m", "time_created": "2023-09-03T05:29:10.293407Z", "time_deleted": null, "time_modified": "2023-09-03T05:29:10.293407Z"}, "pantry_address": null, "project_id": "5e49b6de-cb2d-438d-83af-95c415bbb901", "rcgen": 1, "runtime_state": {"attach_instance_id": null, "disk_state": "creating", "gen": 1, "time_updated": "2023-09-03T05:29:10.293406Z"}, "size": 858993459200, "slot": null, "volume_id": "cb68ad8a-64ab-4ce6-bede-b60ddef9aed5"}
  undo_finished | NULL
  undo_started  | NULL
  started       | NULL
  succeeded     | [[{"identity": {"id": "23dca27d-c79b-4930-a817-392e8aeaa4c1", "time_created": "2023-08-30T18:59:10.758512Z", "time_modified": "2023-08-30T18:59:10.758512Z"}, "ip": "fd00:1122:3344:105::e", "kind": "Crucible", "pool_id": "57650e05-36ff-4de8-865f-b9562bdb67f5", "port": 32345, "rcgen": 1, "size_used": 858993459200, "time_deleted": null}, {"block_size": 512, "blocks_per_extent": 131072, "dataset_id": "23dca27d-c79b-4930-a817-392e8aeaa4c1", "extent_count": 12800, "identity": {"id": "65b01b8d-ccbf-4dbb-adf9-14eb5d41eeb0", "time_created": "2023-09-03T05:29:10.362952Z", "time_modified": "2023-09-03T05:29:10.362952Z"}, "volume_id": "cb68ad8a-64ab-4ce6-bede-b60ddef9aed5"}], [{"identity": {"id": "1876cdcf-b2e7-4b79-ad2e-67df716e1860", "time_created": "2023-08-30T18:59:10.758513Z", "time_modified": "2023-08-30T18:59:10.758513Z"}, "ip": "fd00:1122:3344:10a::8", "kind": "Crucible", "pool_id": "d4c6bdc6-5e99-4f6c-b57a-9bfcb9a76be4", "port": 32345, "rcgen": 1, "size_used": 966367641600, "time_deleted": null}, {"block_size": 512, "blocks_per_extent": 131072, "dataset_id": "1876cdcf-b2e7-4b79-ad2e-67df716e1860", "extent_count": 12800, "identity": {"id": "0d0bfa0f-a2b9-46b4-b8fc-a211c439611f", "time_created": "2023-09-03T05:29:10.362952Z", "time_modified": "2023-09-03T05:29:10.362952Z"}, "volume_id": "cb68ad8a-64ab-4ce6-bede-b60ddef9aed5"}], [{"identity": {"id": "4d20175a-588b-44b8-8b9c-b16c6c3a97a0", "time_created": "2023-08-30T18:59:10.758511Z", "time_modified": "2023-08-30T18:59:10.758511Z"}, "ip": "fd00:1122:3344:108::b", "kind": "Crucible", "pool_id": "a726cacd-fa35-4ed2-ade6-31ad928b24cb", "port": 32345, "rcgen": 1, "size_used": 2695091978240, "time_deleted": null}, {"block_size": 512, "blocks_per_extent": 131072, "dataset_id": "4d20175a-588b-44b8-8b9c-b16c6c3a97a0", "extent_count": 12800, "identity": {"id": "aad5cb12-f873-4d4c-b888-7db99bf0a186", "time_created": "2023-09-03T05:29:10.362952Z", "time_modified": "2023-09-03T05:29:10.362952Z"}, "volume_id": "cb68ad8a-64ab-4ce6-bede-b60ddef9aed5"}]]
  undo_finished | NULL
  undo_started  | NULL
  started       | NULL
  succeeded     | null
  undo_finished | NULL
  undo_started  | NULL
  failed        | {"ActionFailed": {"source_error": {"InternalError": {"internal_message": "Communication Error: error sending request for url (http://[fd00:1122:3344:108::b]:32345/crucible/0/regions): error trying to connect: tcp connect error: Connection refused (os error 146)"}}}}
  started       | NULL
  started       | NULL
  succeeded     | null
  undo_finished | NULL
  undo_started  | NULL
(26 rows)

root@[fd00:1122:3344:105::3]:32221/omicron> select * from region where volume_id = 'cb68ad8a-64ab-4ce6-bede-b60ddef9aed5';
  id | time_created | time_modified | dataset_id | volume_id | block_size | blocks_per_extent | extent_count
-----+--------------+---------------+------------+-----------+------------+-------------------+---------------
(0 rows)


Time: 2ms total (execution 2ms / network 0ms)

root@[fd00:1122:3344:105::3]:32221/omicron> select * from disk where volume_id = 'cb68ad8a-64ab-4ce6-bede-b60ddef9aed5';
                   id                  |       name        |                     description                     |         time_created          |         time_modified         |         time_deleted          | rcgen |              project_id              |              volume_id               | disk_state | attach_instance_id | state_generation | slot |      time_state_updated       |  size_bytes  | block_size | origin_snapshot |             origin_image             | pantry_address
---------------------------------------+-------------------+-----------------------------------------------------+-------------------------------+-------------------------------+-------------------------------+-------+--------------------------------------+--------------------------------------+------------+--------------------+------------------+------+-------------------------------+--------------+------------+-----------------+--------------------------------------+-----------------
  b97593f4-616c-442c-999b-5210da2eab57 | one-each-32c-128m | cb6eb1e9-69fd-40ad-9373-83926f8b32d9 test instance  | 2023-09-03 05:29:10.293407+00 | 2023-09-03 05:29:10.293407+00 | 2023-09-03 05:29:31.641912+00 |     1 | 5e49b6de-cb2d-438d-83af-95c415bbb901 | cb68ad8a-64ab-4ce6-bede-b60ddef9aed5 | destroyed  | NULL               |                1 | NULL | 2023-09-03 05:29:10.293406+00 | 858993459200 |        512 | NULL            | cb6eb1e9-69fd-40ad-9373-83926f8b32d9 | NULL
(1 row)

As part of the fix of this ticket, we probably need some support tool to recalculate the space used, fix the values in the region table, purge orphan regions, and so on. The utility can then be used against our internal lab environments and customer racks.

For posterity: I manually deleted the entry for d9968d58-5e4f-4349-aaf9-f88024ebf8b4 from /data/crucible.json and ran svcadm clear agent for now to bring up the agent. This or other crucible zones that have orphan region issues may soon run into the "out of space" error again.