01KKCXEKGA7A145Y5XC05PYVH9: test-up-encrypted

BasicConfig {
    output_rules: [
        "%/tmp/test_up*/*.txt",
        "%/tmp/test_up*/dsc/*.txt",
        "%/tmp/debug/*",
        "/tmp/core.*",
    ],
    rust_toolchain: None,
    target: Some(
        "helios-2.0",
    ),
    access_repos: [],
    publish: [],
    skip_clone: true,
}

Buildomat Job: 01KKCXF319B2QD1WWD9MJ2874G

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-03-10T22:38:56.664Zjob dependencies complete; ready to run (waiting for 17 m 8 s)
22026-03-10T22:40:37.296Zjob assigned to worker 01KKCYES20RG4Y62MWJVSGMC3D [factory aws, i-05ce413768c14ca38] (queued for 1 m 40 s)
32026-03-10T22:40:45.237Zdownloading input: /input/build/work/bins/crucible-downstairs.gz
42026-03-10T22:40:47.040Zdownloaded input: /input/build/work/bins/crucible-downstairs.gz
52026-03-10T22:40:47.051Zdownloading input: /input/build/work/bins/crucible-hammer.gz
62026-03-10T22:40:48.607Zdownloaded input: /input/build/work/bins/crucible-hammer.gz
72026-03-10T22:40:48.607Zdownloading input: /input/build/work/bins/crutest.gz
82026-03-10T22:40:50.141Zdownloaded input: /input/build/work/bins/crutest.gz
92026-03-10T22:40:50.145Zdownloading input: /input/build/work/bins/dsc.gz
102026-03-10T22:40:50.866Zdownloaded input: /input/build/work/bins/dsc.gz
112026-03-10T22:40:50.870Zdownloading input: /input/build/work/scripts/perf-downstairs-tick.d
122026-03-10T22:40:50.896Zdownloaded input: /input/build/work/scripts/perf-downstairs-tick.d
132026-03-10T22:40:50.897Zdownloading input: /input/build/work/scripts/test_ds.sh
142026-03-10T22:40:50.926Zdownloaded input: /input/build/work/scripts/test_ds.sh
152026-03-10T22:40:50.929Zdownloading input: /input/build/work/scripts/test_live_repair.sh
162026-03-10T22:40:50.956Zdownloaded input: /input/build/work/scripts/test_live_repair.sh
172026-03-10T22:40:50.959Zdownloading input: /input/build/work/scripts/test_repair.sh
182026-03-10T22:40:50.984Zdownloaded input: /input/build/work/scripts/test_repair.sh
192026-03-10T22:40:50.984Zdownloading input: /input/build/work/scripts/test_replay.sh
202026-03-10T22:40:51.013Zdownloaded input: /input/build/work/scripts/test_replay.sh
212026-03-10T22:40:51.013Zdownloading input: /input/build/work/scripts/test_up.sh
222026-03-10T22:40:51.041Zdownloaded input: /input/build/work/scripts/test_up.sh
232026-03-10T22:40:51.044Zdownloading input: /input/build/work/scripts/upstairs_info.d
242026-03-10T22:40:51.069Zdownloaded input: /input/build/work/scripts/upstairs_info.d
252026-03-10T22:40:51.072Zdownloading input: /input/build/tmp/cargo-test-out.log
262026-03-10T22:40:51.605Zdownloaded input: /input/build/tmp/cargo-test-out.log
 
272026-03-10T22:40:51.605Zstarting task 0: "setup"
282026-03-10T22:40:51.609Z++ uname -s
292026-03-10T22:40:51.612Z+ kern=SunOS
302026-03-10T22:40:51.612Z+ build_user=build
312026-03-10T22:40:51.612Z+ build_uid=12345
322026-03-10T22:40:51.612Z+ work_dir=/work
332026-03-10T22:40:51.612Z+ input_dir=/input
342026-03-10T22:40:51.612Z+ [[ 0 == 12345 ]]
352026-03-10T22:40:51.612Z+ case "$kern" in
362026-03-10T22:40:51.612Z+ groupadd -g 12345 build
372026-03-10T22:40:51.615Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
382026-03-10T22:40:53.625Z+ zfs create -o mountpoint=/work rpool/work
392026-03-10T22:40:53.979Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
402026-03-10T22:40:53.982Z+ home_fs=zfs
412026-03-10T22:40:53.982Z+ [[ zfs == autofs ]]
422026-03-10T22:40:53.982Z+ mkdir -p /home/build
432026-03-10T22:40:53.985Z+ chown build:build /home/build /work
442026-03-10T22:40:54.985Z+ chmod 0700 /home/build /work
452026-03-10T22:40:54.988Zprocess exited: duration 3384 ms, exit code 0
 
462026-03-10T22:40:54.995Zstarting task 1: "authentication"
472026-03-10T22:40:55.013Zprocess exited: duration 19 ms, exit code 0
 
482026-03-10T22:40:55.019Zstarting task 2: "build"
492026-03-10T22:40:55.023Z+ banner cores
502026-03-10T22:40:55.026Z
512026-03-10T22:40:55.026Z #### #### ##### ###### ####
522026-03-10T22:40:55.026Z # # # # # # # #
532026-03-10T22:40:55.026Z # # # # # ##### ####
542026-03-10T22:40:55.026Z # # # ##### # #
552026-03-10T22:40:55.026Z # # # # # # # # #
562026-03-10T22:40:55.026Z #### #### # # ###### ####
572026-03-10T22:40:55.026Z
582026-03-10T22:40:55.026Z+ pfexec coreadm -i /tmp/core.%f.%p -g /tmp/core.%f.%p -e global -e log -e proc-setid -e global-setid
592026-03-10T22:40:55.034Z+ echo 'input bins dir contains:'
602026-03-10T22:40:55.037Zinput bins dir contains:
612026-03-10T22:40:55.037Z+ ls -ltr /input/build/work/bins
622026-03-10T22:40:55.037Ztotal 1013026
632026-03-10T22:40:55.037Z-rw-r--r-- 1 root root 154130375 Mar 10 22:40 crucible-downstairs.gz
642026-03-10T22:40:55.037Z-rw-r--r-- 1 root root 141651354 Mar 10 22:40 crucible-hammer.gz
652026-03-10T22:40:55.037Z-rw-r--r-- 1 root root 150728737 Mar 10 22:40 crutest.gz
662026-03-10T22:40:55.037Z-rw-r--r-- 1 root root 71807752 Mar 10 22:40 dsc.gz
672026-03-10T22:40:55.037Z+ banner unpack
682026-03-10T22:40:55.040Z
692026-03-10T22:40:55.040Z # # # # ##### ## #### # #
702026-03-10T22:40:55.040Z # # ## # # # # # # # # #
712026-03-10T22:40:55.040Z # # # # # # # # # # ####
722026-03-10T22:40:55.040Z # # # # # ##### ###### # # #
732026-03-10T22:40:55.041Z # # # ## # # # # # # #
742026-03-10T22:40:55.041Z #### # # # # # #### # #
752026-03-10T22:40:55.041Z
762026-03-10T22:40:55.041Z+ mkdir -p /var/tmp/bins
772026-03-10T22:40:55.041Z+ for t in "$input/bins/"*.gz
782026-03-10T22:40:55.041Z++ basename /input/build/work/bins/crucible-downstairs.gz
792026-03-10T22:40:55.044Z+ b=crucible-downstairs.gz
802026-03-10T22:40:55.044Z+ b=crucible-downstairs
812026-03-10T22:40:55.044Z+ gunzip
822026-03-10T22:40:58.081Z+ chmod +x /var/tmp/bins/crucible-downstairs
832026-03-10T22:40:58.084Z+ for t in "$input/bins/"*.gz
842026-03-10T22:40:58.084Z++ basename /input/build/work/bins/crucible-hammer.gz
852026-03-10T22:40:58.084Z+ b=crucible-hammer.gz
862026-03-10T22:40:58.084Z+ b=crucible-hammer
872026-03-10T22:40:58.084Z+ gunzip
882026-03-10T22:41:00.812Z+ chmod +x /var/tmp/bins/crucible-hammer
892026-03-10T22:41:00.816Z+ for t in "$input/bins/"*.gz
902026-03-10T22:41:00.816Z++ basename /input/build/work/bins/crutest.gz
912026-03-10T22:41:00.816Z+ b=crutest.gz
922026-03-10T22:41:00.816Z+ b=crutest
932026-03-10T22:41:00.816Z+ gunzip
942026-03-10T22:41:03.763Z+ chmod +x /var/tmp/bins/crutest
952026-03-10T22:41:03.767Z+ for t in "$input/bins/"*.gz
962026-03-10T22:41:03.767Z++ basename /input/build/work/bins/dsc.gz
972026-03-10T22:41:03.771Z+ b=dsc.gz
982026-03-10T22:41:03.771Z+ b=dsc
992026-03-10T22:41:03.771Z+ gunzip
1002026-03-10T22:41:05.142Z+ chmod +x /var/tmp/bins/dsc
1012026-03-10T22:41:05.145Z+ export BINDIR=/var/tmp/bins
1022026-03-10T22:41:05.145Z+ BINDIR=/var/tmp/bins
1032026-03-10T22:41:05.145Z+ export RUST_BACKTRACE=1
1042026-03-10T22:41:05.145Z+ RUST_BACKTRACE=1
1052026-03-10T22:41:05.145Z+ jobpid=1155
1062026-03-10T22:41:05.145Z+ echo 'Setup debug logging'
1072026-03-10T22:41:05.145ZSetup debug logging
1082026-03-10T22:41:05.145Z+ mkdir /tmp/debug
1092026-03-10T22:41:05.145Z+ sleep 3600
1102026-03-10T22:41:05.148Z+ psrinfo -v
1112026-03-10T22:41:05.151Z+ df -h
1122026-03-10T22:41:05.157Z+ prstat -d d -mLc 1
1132026-03-10T22:41:05.160Z+ iostat -T d -xn 1
1142026-03-10T22:41:05.160Z+ mpstat -T d 1
1152026-03-10T22:41:05.160Z+ vmstat -T d -p 1
1162026-03-10T22:41:05.160Z+ pfexec dtrace -Z -s /input/build/work/scripts/perf-downstairs-tick.d
1172026-03-10T22:41:05.163Z+ banner test_up_encrypted
1182026-03-10T22:41:05.163Z+ pfexec dtrace -Z -s /input/build/work/scripts/upstairs_info.d
1192026-03-10T22:41:05.163Z
1202026-03-10T22:41:05.163Z ##### ###### #### ##### # # ##### ###### # #
1212026-03-10T22:41:05.163Z # # # # # # # # # ## #
1222026-03-10T22:41:05.163Z # ##### #### # # # # # ##### # # #
1232026-03-10T22:41:05.163Z # # # # # # ##### # # # #
1242026-03-10T22:41:05.163Z # # # # # # # # # # ##
1252026-03-10T22:41:05.163Z # ###### #### # ####### #### # ####### ###### # #
1262026-03-10T22:41:05.163Z
1272026-03-10T22:41:05.164Z+ ptime -m bash /input/build/work/scripts/test_up.sh -N encrypted
1282026-03-10T22:41:05.172Z/input/build/work
1292026-03-10T22:41:05.181ZTurn off color for downstairs dump
1302026-03-10T22:41:05.196ZUpstairs using key: m5OOV55XDQrfHzhii/D/29BkbYdehoLswmIDYCkbVcc=
1312026-03-10T22:41:05.199Zdsc output goes to /tmp/test_up-build/dsc-out.txt
1322026-03-10T22:41:05.199ZCreating 3 downstairs regions
1332026-03-10T22:41:05.476ZStarting 3 downstairs
1342026-03-10T22:41:05.479Zdsc started at PID: 1201
1352026-03-10T22:41:10.543ZDisable automatic restart on all downstairs
1362026-03-10T22:41:10.561Z
1372026-03-10T22:41:10.561ZBegin tests, output goes to /tmp/test_up-build/test_up_out.txt
1382026-03-10T22:41:10.564ZRunning test: span
1392026-03-10T22:41:14.649ZCompleted test: span
1402026-03-10T22:41:19.653ZRunning test: big
1412026-03-10T22:41:23.879ZCompleted test: big
1422026-03-10T22:41:28.886ZRunning test: dep
1432026-03-10T22:42:15.101ZCompleted test: dep
1442026-03-10T22:42:18.027ZRunning test: balloon
1452026-03-10T22:42:53.261ZCompleted test: balloon
1462026-03-10T22:42:58.267ZRunning test: deactivate
1472026-03-10T22:43:02.754ZCompleted test: deactivate
1482026-03-10T22:43:07.737ZRunning hammer
1492026-03-10T22:43:23.208ZRun repair tests
1502026-03-10T22:43:23.212Z/var/tmp/bins/crutest fill -g 31 -q --key m5OOV55XDQrfHzhii/D/29BkbYdehoLswmIDYCkbVcc= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file
1512026-03-10T22:43:23.235Z{"msg":"Use this region info from dsc: RegionExtentInfo { block_size: 4096, blocks_per_extent: 10, extent_count: 5 }","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.391337099Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"task":"crutest"}
1522026-03-10T22:43:23.241Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.391698895Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"task":"crutest"}
1532026-03-10T22:43:23.241Z{"msg":"SV 0 has targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.392700108Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"task":"crutest"}
1542026-03-10T22:43:23.241Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.392986599Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238}
1552026-03-10T22:43:23.241Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"30900e8598062c7a51387ea19c609caa76585ff9\",\n git_commit_timestamp: \"2026-03-10T22:17:59.000000000Z\",\n git_branch: \"renovate/rand_chacha-0.x\",\n rustc_semver: \"1.90.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"1159e78c4747b02ef996e55082b704c09b970588\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: true,\n opt_level: 0,\n}","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393027186Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238}
1562026-03-10T22:43:23.241Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393040565Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238}
1572026-03-10T22:43:23.241Z{"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 10, shift: 12 }, extent_count: 5, uuid: 00000000-0000-0000-0000-000000000000, encrypted: true, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393059714Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238}
1582026-03-10T22:43:23.241Z{"msg":"Crucible e88165e8-96ab-443d-a3ac-707d2f832e44 has session id: cdeb8ec5-e1cd-497b-857e-30b019703ef8","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393459157Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1592026-03-10T22:43:23.241Z{"msg":"Upstairs opts: Upstairs UUID: e88165e8-96ab-443d-a3ac-707d2f832e44, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: true, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393491135Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1602026-03-10T22:43:23.242Z{"msg":"Crucible stats registered with UUID: e88165e8-96ab-443d-a3ac-707d2f832e44","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393507234Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1612026-03-10T22:43:23.242Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:22.393521013Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1622026-03-10T22:43:23.242Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393661194Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"io task","client":"1","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1632026-03-10T22:43:23.242Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393689772Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"io task","client":"0","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1642026-03-10T22:43:23.242Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393705751Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"io task","client":"2","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1652026-03-10T22:43:23.242Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393897488Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"task":"crutest"}
1662026-03-10T22:43:23.242Z{"msg":"The guest has requested activation with gen:31","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393916607Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238}
1672026-03-10T22:43:23.242Z{"msg":"e88165e8-96ab-443d-a3ac-707d2f832e44 active request set","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393929086Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1682026-03-10T22:43:23.242Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393942615Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"client":"0","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1692026-03-10T22:43:23.243Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393961914Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"client":"1","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1702026-03-10T22:43:23.243Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393977403Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"client":"2","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1712026-03-10T22:43:23.243Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.393992412Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"io task","client":"0","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1722026-03-10T22:43:23.243Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.394007811Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"io task","client":"2","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1732026-03-10T22:43:23.243Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.394023259Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"io task","client":"1","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1742026-03-10T22:43:23.243Z{"msg":"ds_connection connected from Ok(127.0.0.1:57588)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.394047098Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"io task","client":"2","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1752026-03-10T22:43:23.243Z{"msg":"ds_connection connected from Ok(127.0.0.1:41108)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.394067037Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"io task","client":"1","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1762026-03-10T22:43:23.243Z{"msg":"ds_connection connected from Ok(127.0.0.1:64334)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.394083605Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"io task","client":"0","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1772026-03-10T22:43:23.243Z{"msg":"downstairs client at Some(127.0.0.1:8830) has region UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.394891111Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"client":"2","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1782026-03-10T22:43:23.244Z{"msg":"downstairs client at Some(127.0.0.1:8810) has region UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.394949187Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"client":"0","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1792026-03-10T22:43:23.244Z{"msg":"downstairs client at Some(127.0.0.1:8820) has region UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.394967846Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"client":"1","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1802026-03-10T22:43:23.248Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395115666Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1812026-03-10T22:43:23.248Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395148384Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1822026-03-10T22:43:23.249Z{"msg":"[0]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395226479Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1832026-03-10T22:43:23.249Z{"msg":"[0]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395242718Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1842026-03-10T22:43:23.249Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395258277Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1852026-03-10T22:43:23.249Z{"msg":"[1]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395273596Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1862026-03-10T22:43:23.249Z{"msg":"[1]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395288875Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1872026-03-10T22:43:23.249Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395304284Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1882026-03-10T22:43:23.249Z{"msg":"[2]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395319583Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1892026-03-10T22:43:23.249Z{"msg":"[2]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395334202Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1902026-03-10T22:43:23.250Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395349211Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1912026-03-10T22:43:23.250Z{"msg":"Wait for a query_work_queue command to finish before sending IO
1922026-03-10T22:43:23.250ZMax found gen is 26","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395368289Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1932026-03-10T22:43:23.250Z{"msg":"Generation requested: 31 >= found:26","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395383318Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1942026-03-10T22:43:23.250Z{"msg":"Next flush: 1500","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395397037Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1952026-03-10T22:43:23.250Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395411487Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"":"downstairs","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1962026-03-10T22:43:23.250Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395434305Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1972026-03-10T22:43:23.250Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395448474Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"client":"0","":"downstairs","session_id":"Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
1982026-03-10T22:43:23.250Zcdeb8ec5-e1cd-497b-857e-30b019703ef8"}
1992026-03-10T22:43:23.250Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395465223Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"client":"1","":"downstairs","session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
2002026-03-10T22:43:23.250Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395479652Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"client":"2","":"downstairs",Fill test
2012026-03-10T22:43:23.250Z"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
2022026-03-10T22:43:23.251Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395496461Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
2032026-03-10T22:43:23.251Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.39551044Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
2042026-03-10T22:43:23.251Z{"msg":"e88165e8-96ab-443d-a3ac-707d2f832e44 is now active with session: cdeb8ec5-e1cd-497b-857e-30b019703ef8","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395526769Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
2052026-03-10T22:43:23.251Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395540128Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238,"session_id":"cdeb8ec5-e1cd-497b-857e-30b019703ef8"}
2062026-03-10T22:43:23.251Z{"msg":"The guest has finished waiting for activation with:31","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395554057Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238}
2072026-03-10T22:43:23.251Z{"msg":"Activated sub_volume e88165e8-96ab-443d-a3ac-707d2f832e44","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:22.395566176Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238}
2082026-03-10T22:43:23.275ZRead and Verify all blocks (0..50 range:false)
2092026-03-10T22:43:23.309ZWrote out file "/var/tmp/test_up-build/verify_file"
2102026-03-10T22:43:23.309ZCLIENT: Tests done. All submitted work has been ACK'd
2112026-03-10T22:43:23.313Z----------------------------------------------------------------
2122026-03-10T22:43:23.313Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:1
2132026-03-10T22:43:23.313ZStates: Active Active Active
2142026-03-10T22:43:23.313ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2152026-03-10T22:43:23.313Z 1002 Acked Read 50 Done Done Done false
2162026-03-10T22:43:23.313Z STATES DS:0 DS:1 DS:2 TOTAL
2172026-03-10T22:43:23.313Z Sent 0 0 0 0
2182026-03-10T22:43:23.313Z Done 1 1 1 3
2192026-03-10T22:43:23.313Z Skipped 0 0 0 0
2202026-03-10T22:43:23.313Z Error 0 0 0 0
2212026-03-10T22:43:23.314ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
2222026-03-10T22:43:23.314ZDownstairs last five completed: 1001 1000
2232026-03-10T22:43:23.314ZUpstairs last five completed: 1002 1001 1000
2242026-03-10T22:43:23.314ZCLIENT: Up:0 ds:1 act:3
2252026-03-10T22:43:27.310Z----------------------------------------------------------------
2262026-03-10T22:43:27.310Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:0
2272026-03-10T22:43:27.310ZDownstairs last five completed: 1003 1002 1001 1000
2282026-03-10T22:43:27.310ZUpstairs last five completed: 1003 1002 1001 1000
2292026-03-10T22:43:27.310ZCLIENT: Up:0 ds:0 act:3
2302026-03-10T22:43:27.310ZCLIENT: All crucible jobs finished, exiting program
2312026-03-10T22:43:27.314Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:26.466200369Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1238}
2322026-03-10T22:43:27.318ZRepair setup passed
2332026-03-10T22:43:27.322ZCopy the region for /var/tmp/test_up-build/8830
2342026-03-10T22:43:27.325Zcp -r /var/tmp/test_up-build/8830 /var/tmp/test_up-build/previous
2352026-03-10T22:43:27.325Z/var/tmp/bins/crutest fill -g 32 -q --key m5OOV55XDQrfHzhii/D/29BkbYdehoLswmIDYCkbVcc= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
2362026-03-10T22:43:27.349Z{"msg":"Use this region info from dsc: RegionExtentInfo { block_size: 4096, blocks_per_extent: 10, extent_count: 5 }","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.504539832Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"task":"crutest"}
2372026-03-10T22:43:27.354Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.504889649Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"task":"crutest"}
2382026-03-10T22:43:27.354Z{"msg":"SV 0 has targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.505937218Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"task":"crutest"}
2392026-03-10T22:43:27.354Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.50621795Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244}
2402026-03-10T22:43:27.354Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"30900e8598062c7a51387ea19c609caa76585ff9\",\n git_commit_timestamp: \"2026-03-10T22:17:59.000000000Z\",\n git_branch: \"renovate/rand_chacha-0.x\",\n rustc_semver: \"1.90.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"1159e78c4747b02ef996e55082b704c09b970588\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: true,\n opt_level: 0,\n}","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.506254797Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244}
2412026-03-10T22:43:27.354Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.506268656Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244}
2422026-03-10T22:43:27.354Z{"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 10, shift: 12 }, extent_count: 5, uuid: 00000000-0000-0000-0000-000000000000, encrypted: true, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.506288135Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244}
2432026-03-10T22:43:27.354Z{"msg":"Crucible d217c08d-1b44-462b-9b36-ec9a610c7aad has session id: 69769d3d-45d3-462e-8329-7c157b18c422","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.506694498Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2442026-03-10T22:43:27.354Z{"msg":"Upstairs opts: Upstairs UUID: d217c08d-1b44-462b-9b36-ec9a610c7aad, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: true, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.506730835Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2452026-03-10T22:43:27.354Z{"msg":"Crucible stats registered with UUID: d217c08d-1b44-462b-9b36-ec9a610c7aad","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.506747184Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2462026-03-10T22:43:27.354Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:26.506761083Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2472026-03-10T22:43:27.354Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.506936302Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"io task","client":"1","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2482026-03-10T22:43:27.354Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.506989768Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2492026-03-10T22:43:27.354Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507018316Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"io task","client":"0","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2502026-03-10T22:43:27.354Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507142078Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"task":"crutest"}
2512026-03-10T22:43:27.354Z{"msg":"The guest has requested activation with gen:32","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507164666Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244}
2522026-03-10T22:43:27.354Z{"msg":"d217c08d-1b44-462b-9b36-ec9a610c7aad active request set","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507210963Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2532026-03-10T22:43:27.355Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507225732Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"client":"0","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2542026-03-10T22:43:27.355Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507241621Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"client":"1","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2552026-03-10T22:43:27.355Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.50725648Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"client":"2","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2562026-03-10T22:43:27.355Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507271179Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2572026-03-10T22:43:27.355Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507292138Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"io task","client":"0","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2582026-03-10T22:43:27.355Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507307407Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"io task","client":"1","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2592026-03-10T22:43:27.355Z{"msg":"ds_connection connected from Ok(127.0.0.1:49428)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507349564Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"io task","client":"0","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2602026-03-10T22:43:27.355Z{"msg":"ds_connection connected from Ok(127.0.0.1:57174)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507386901Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"io task","client":"1","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2612026-03-10T22:43:27.355Z{"msg":"ds_connection connected from Ok(127.0.0.1:35171)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.507420399Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2622026-03-10T22:43:27.359Z{"msg":"downstairs client at Some(127.0.0.1:8810) has region UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508141141Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"client":"0","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2632026-03-10T22:43:27.359Z{"msg":"downstairs client at Some(127.0.0.1:8820) has region UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508178048Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"client":"1","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2642026-03-10T22:43:27.359Z{"msg":"downstairs client at Some(127.0.0.1:8830) has region UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508200697Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"client":"2","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2652026-03-10T22:43:27.359Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508377715Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2662026-03-10T22:43:27.359Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508418222Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2672026-03-10T22:43:27.359Z{"msg":"[0]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508495177Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2682026-03-10T22:43:27.359Z{"msg":"[0]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508511396Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2692026-03-10T22:43:27.359Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508526655Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2702026-03-10T22:43:27.359Z{"msg":"[1]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508542664Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2712026-03-10T22:43:27.359Z{"msg":"[1]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508558263Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2722026-03-10T22:43:27.359Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508573432Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2732026-03-10T22:43:27.359Z{"msg":"[2]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508588751Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2742026-03-10T22:43:27.359Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.50860355Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2752026-03-10T22:43:27.359Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508618949Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2762026-03-10T22:43:27.359Z{"msg":"Max found gen is 32","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508633248Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2772026-03-10T22:43:27.359Z{"msg":"Generation requested: 32 >= found:32","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO
2782026-03-10T22:43:27.359Z,"time":"2026-03-10T22:43:26.508648377Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2792026-03-10T22:43:27.359Z{"msg":"Next flush: 1501","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508666636Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2802026-03-10T22:43:27.360Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508680785Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"":"downstairs","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2812026-03-10T22:43:27.360Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508695654Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2822026-03-10T22:43:27.360Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508709263Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"client":"0","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2832026-03-10T22:43:27.360Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508724002Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"client":"1","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2842026-03-10T22:43:27.360Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508738521Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"client":"2","":"downstairs","session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2852026-03-10T22:43:27.360Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2862026-03-10T22:43:27.360Z2026-03-10T22:43:26.50875339Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2872026-03-10T22:43:27.360Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508769889Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2882026-03-10T22:43:27.360Z{"msg":"d217c08d-1b44-462b-9b36-ec9a610c7aad is now active with session: 69769d3d-45d3-462e-8329-7c157b18c422","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508786088Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2892026-03-10T22:43:27.360Z{"msg":"The guest has finished waiting for activation with:32","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508800197Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244}
2902026-03-10T22:43:27.360Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508811786Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244,"session_id":"69769d3d-45d3-462e-8329-7c157b18c422"}
2912026-03-10T22:43:27.360Z{"msg":"Activated sub_volume d217c08d-1b44-462b-9b36-ec9a610c7aad","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:26.508826025Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244}
2922026-03-10T22:43:27.360ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
2932026-03-10T22:43:27.360ZFill test
2942026-03-10T22:43:27.388ZRead and Verify all blocks (0..50 range:false)
2952026-03-10T22:43:27.422ZWrote out file "/var/tmp/test_up-build/verify_file"
2962026-03-10T22:43:27.422ZCLIENT: Tests done. All submitted work has been ACK'd
2972026-03-10T22:43:27.425Z----------------------------------------------------------------
2982026-03-10T22:43:27.425Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:1
2992026-03-10T22:43:27.425ZStates: Active Active Active
3002026-03-10T22:43:27.425ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
3012026-03-10T22:43:27.425Z 1002 Acked Read 50 Done Done Done false
3022026-03-10T22:43:27.426Z STATES DS:0 DS:1 DS:2 TOTAL
3032026-03-10T22:43:27.426Z Sent 0 0 0 0
3042026-03-10T22:43:27.426Z Done 1 1 1 3
3052026-03-10T22:43:27.426Z Skipped 0 0 0 0
3062026-03-10T22:43:27.426Z Error 0 0 0 0
3072026-03-10T22:43:27.426ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
3082026-03-10T22:43:27.426ZDownstairs last five completed: 1001 1000
3092026-03-10T22:43:27.426ZUpstairs last five completed: 1002 1001 1000
3102026-03-10T22:43:27.426ZCLIENT: Up:0 ds:1 act:3
3112026-03-10T22:43:31.424Z----------------------------------------------------------------
3122026-03-10T22:43:31.424Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:0
3132026-03-10T22:43:31.424ZDownstairs last five completed: 1003 1002 1001 1000
3142026-03-10T22:43:31.424ZUpstairs last five completed: 1003 1002 1001 1000
3152026-03-10T22:43:31.425ZCLIENT: Up:0 ds:0 act:3
3162026-03-10T22:43:31.425ZCLIENT: All crucible jobs finished, exiting program
3172026-03-10T22:43:31.428Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:30.579766639Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1244}
3182026-03-10T22:43:31.431ZRepair part 1 passed
3192026-03-10T22:43:31.431Z
3202026-03-10T22:43:31.431ZKill the current downstairs
3212026-03-10T22:43:31.487ZDownstairs 2 stopped
3222026-03-10T22:43:31.487Zmv /var/tmp/test_up-build/8830 /var/tmp/test_up-build/new
3232026-03-10T22:43:31.490ZNow put back the original so we have a mismatch
3242026-03-10T22:43:31.490Zmv /var/tmp/test_up-build/previous /var/tmp/test_up-build/8830
3252026-03-10T22:43:31.493ZRestart downstairs with old directory
3262026-03-10T22:43:31.509Z/var/tmp/bins/crucible-downstairs dump --no-color -d /var/tmp/test_up-build/8810 -d /var/tmp/test_up-build/8820 -d /var/tmp/test_up-build/8830
3272026-03-10T22:43:31.522ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
3282026-03-10T22:43:31.525Z 0 000-009 32 32 31 1501 1501 1500 F F F <---
3292026-03-10T22:43:31.525Z 1 010-019 32 32 31 1501 1501 1500 F F F <---
3302026-03-10T22:43:31.525Z 2 020-029 32 32 31 1501 1501 1500 F F F <---
3312026-03-10T22:43:31.525Z 3 030-039 32 32 31 1501 1501 1500 F F F <---
3322026-03-10T22:43:31.525Z 4 040-049 32 32 31 1501 1501 1500 F F F <---
3332026-03-10T22:43:31.525ZMax gen: 32, Max flush: 1501
3342026-03-10T22:43:31.789ZError: Difference in extent metadata found!
3352026-03-10T22:43:31.789Z
3362026-03-10T22:43:31.789ZStack backtrace:
3372026-03-10T22:43:31.789Z 0: anyhow::error::<impl anyhow::Error>::msg
3382026-03-10T22:43:31.789Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/backtrace.rs:27:14
3392026-03-10T22:43:31.789Z 1: anyhow::__private::format_err
3402026-03-10T22:43:31.789Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/lib.rs:695:13
3412026-03-10T22:43:31.809Zdump test found error as expected
3422026-03-10T22:43:31.812Z
3432026-03-10T22:43:31.812Z
3442026-03-10T22:43:31.812Z/var/tmp/bins/crutest verify --range -g 33 -q --key m5OOV55XDQrfHzhii/D/29BkbYdehoLswmIDYCkbVcc= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
3452026-03-10T22:43:31.833Z{"msg":"Use this region info from dsc: RegionExtentInfo { block_size: 4096, blocks_per_extent: 10, extent_count: 5 }","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.989001079Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"task":"crutest"}
3462026-03-10T22:43:31.837Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.989347606Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"task":"crutest"}
3472026-03-10T22:43:31.837Z{"msg":"SV 0 has targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.990366708Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"task":"crutest"}
3482026-03-10T22:43:31.837Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.990664128Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252}
3492026-03-10T22:43:31.837Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"30900e8598062c7a51387ea19c609caa76585ff9\",\n git_commit_timestamp: \"2026-03-10T22:17:59.000000000Z\",\n git_branch: \"renovate/rand_chacha-0.x\",\n rustc_semver: \"1.90.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"1159e78c4747b02ef996e55082b704c09b970588\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: true,\n opt_level: 0,\n}","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.990700895Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252}
3502026-03-10T22:43:31.837Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.990714195Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252}
3512026-03-10T22:43:31.837Z{"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 10, shift: 12 }, extent_count: 5, uuid: 00000000-0000-0000-0000-000000000000, encrypted: true, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.990732823Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252}
3522026-03-10T22:43:31.837Z{"msg":"Crucible 1ffa9f99-fc3f-48c9-9a9e-ed1756c55b6f has session id: 5ccaffef-beb0-488e-9ce0-0ad77bad74f1","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991154805Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3532026-03-10T22:43:31.837Z{"msg":"Upstairs opts: Upstairs UUID: 1ffa9f99-fc3f-48c9-9a9e-ed1756c55b6f, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: true, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991199352Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3542026-03-10T22:43:31.837Z{"msg":"Crucible stats registered with UUID: 1ffa9f99-fc3f-48c9-9a9e-ed1756c55b6f","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991216541Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3552026-03-10T22:43:31.837Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:30.99123053Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3562026-03-10T22:43:31.837Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991359641Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"0","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3572026-03-10T22:43:31.837Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991395889Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"1","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3582026-03-10T22:43:31.837Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991412418Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3592026-03-10T22:43:31.837Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991617694Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"task":"crutest"}
3602026-03-10T22:43:31.837Z{"msg":"The guest has requested activation with gen:33","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991636703Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252}
3612026-03-10T22:43:31.837Z{"msg":"1ffa9f99-fc3f-48c9-9a9e-ed1756c55b6f active request set","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991652992Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3622026-03-10T22:43:31.837Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991668651Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"0","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3632026-03-10T22:43:31.837Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.99168324Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"1","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3642026-03-10T22:43:31.837Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991698579Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3652026-03-10T22:43:31.837Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991713138Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3662026-03-10T22:43:31.837Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991728297Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"0","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3672026-03-10T22:43:31.837Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991743516Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"1","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3682026-03-10T22:43:31.837Z{"msg":"ds_connection connected from Ok(127.0.0.1:45941)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991789013Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"0","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3692026-03-10T22:43:31.838Z{"msg":"ds_connection connected from Ok(127.0.0.1:37852)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.991845119Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"1","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3702026-03-10T22:43:31.838Z{"msg":"ds_connection connect to 127.0.0.1:8830 failure: Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:30.991940622Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3712026-03-10T22:43:31.838Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:30.99197392Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3722026-03-10T22:43:31.838Z{"msg":"downstairs task for 2 stopped due to ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" })","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:30.992039046Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3732026-03-10T22:43:31.838Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.992054695Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3742026-03-10T22:43:31.838Z{"msg":"sleeping for 10s before connecting","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.992075043Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3752026-03-10T22:43:31.841Z{"msg":"downstairs client at Some(127.0.0.1:8820) has region UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.992448988Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"1","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3762026-03-10T22:43:31.841Z{"msg":"downstairs client at Some(127.0.0.1:8810) has region UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.992490386Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"0","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3772026-03-10T22:43:31.841Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.992639576Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3782026-03-10T22:43:31.841Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:30.992679163Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3792026-03-10T22:43:41.839Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:40.993776616Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3802026-03-10T22:43:41.839Z{"msg":"ds_connection connect to 127.0.0.1:8830 failure: Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:40.993844231Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3812026-03-10T22:43:41.842Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:40.99386502Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3822026-03-10T22:43:41.842Z{"msg":"downstairs task for 2 stopped due to ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" })","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:40.993888188Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3832026-03-10T22:43:41.842Z{"msg":"sleeping for 10s before connecting","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:40.993929825Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3842026-03-10T22:43:41.842Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:40.993982052Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3852026-03-10T22:43:51.841Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.994477397Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3862026-03-10T22:43:51.842Z{"msg":"ds_connection connected from Ok(127.0.0.1:35114)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.994588039Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"io task","client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3872026-03-10T22:43:51.847Z{"msg":"downstairs client at Some(127.0.0.1:8830) has region UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.995648898Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3882026-03-10T22:43:51.847Z{"msg":"[0]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.995939549Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3892026-03-10T22:43:51.848Z{"msg":"[0]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.995958087Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3902026-03-10T22:43:51.848Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.995974356Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3912026-03-10T22:43:51.848Z{"msg":"[1]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.995989805Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3922026-03-10T22:43:51.848Z{"msg":"[1]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996006054Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3932026-03-10T22:43:51.848Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996021663Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3942026-03-10T22:43:51.848Z{"msg":"[2]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996037392Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3952026-03-10T22:43:51.848Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996052801Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3962026-03-10T22:43:51.848Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996079479Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3972026-03-10T22:43:51.848Z{"msg":"Max found gen is 33","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996094278Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3982026-03-10T22:43:51.848Z{"msg":"Generation requested: 33 >= found:33","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996110237Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
3992026-03-10T22:43:51.848Z{"msg":"Next flush: 1502","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996124786Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4002026-03-10T22:43:51.848Z{"msg":"extent 0 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996147565Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4012026-03-10T22:43:51.848Z{"msg":"extent:0 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996171633Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4022026-03-10T22:43:51.848Z{"msg":"found dest for source 0 for extent at index 0 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996188442Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4032026-03-10T22:43:51.848Z{"msg":"extent 1 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996211021Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4042026-03-10T22:43:51.848Z{"msg":"extent:1 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996233879Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4052026-03-10T22:43:51.848Z{"msg":"found dest for source 0 for extent at index 1 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996250868Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4062026-03-10T22:43:51.848Z{"msg":"extent 2 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996274096Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4072026-03-10T22:43:51.848Z{"msg":"extent:2 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996297685Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4082026-03-10T22:43:51.848Z{"msg":"found dest for source 0 for extent at index 2 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996314014Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4092026-03-10T22:43:51.848Z{"msg":"extent 3 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996336512Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4102026-03-10T22:43:51.848Z{"msg":"extent:3 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996359391Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4112026-03-10T22:43:51.848Z{"msg":"found dest for source 0 for extent at index 3 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996375719Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4122026-03-10T22:43:51.849Z{"msg":"extent 4 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996398598Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4132026-03-10T22:43:51.849Z{"msg":"extent:4 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996420506Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4142026-03-10T22:43:51.849Z{"msg":"found dest for source 0 for extent at index 4 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996436485Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"mend","":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4152026-03-10T22:43:51.849Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996462224Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"0","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4162026-03-10T22:43:51.849Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996478813Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"1","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4172026-03-10T22:43:51.849Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996494851Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4182026-03-10T22:43:51.849Z{"msg":"Full repair list: {ExtentId(3): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(0): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(4): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(1): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(2): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }}","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.99652096Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4192026-03-10T22:43:51.849Z{"msg":"Task list: [ReconcileIO { id: ReconciliationId(0), op: ExtentFlush { repair_id: ReconciliationId(0), extent_id: ExtentId(3), client_id: ClientId(0), flush_number: 1502, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(1), op: ExtentClose { repair_id: ReconciliationId(1), extent_id: ExtentId(3) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(2), op: ExtentRepair { repair_id: ReconciliationId(2), extent_id: ExtentId(3), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(3), op: ExtentReopen { repair_id: ReconciliationId(3), extent_id: ExtentId(3) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(4), op: ExtentFlush { repair_id: ReconciliationId(4), extent_id: ExtentId(0), client_id: ClientId(0), flush_number: 1502, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(5), op: ExtentClose { repair_id: ReconciliationId(5), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(6), op: ExtentRepair { repair_id: ReconciliationId(6), extent_id: ExtentId(0), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(7), op: ExtentReopen { repair_id: ReconciliationId(7), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(8), op: ExtentFlush { repair_id: ReconciliationId(8), extent_id: ExtentId(4), client_id: ClientId(0), flush_number: 1502, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(9), op: ExtentClose { repair_id: ReconciliationId(9), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(10), op: ExtentRepair { repair_id: ReconciliationId(10), extent_id: ExtentId(4), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(11), op: ExtentReopen { repair_id: ReconciliationId(11), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(12), op: ExtentFlush { repair_id: ReconciliationId(12), extent_id: ExtentId(1), client_id: ClientId(0), flush_number: 1502, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(13), op: ExtentClose { repair_id: ReconciliationId(13), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(14), op: ExtentRepair { repair_id: ReconciliationId(14), extent_id: ExtentId(1), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(15), op: ExtentReopen { repair_id: ReconciliationId(15), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(16), op: ExtentFlush { repair_id: ReconciliationId(16), extent_id: ExtentId(2), client_id: ClientId(0), flush_number: 1502, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(17), op: ExtentClose { repair_id: ReconciliationId(17), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(18), op: ExtentRepair { repair_id: ReconciliationId(18), extent_id: ExtentId(2), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(19), op: ExtentReopen { repair_id: ReconciliationId(19), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }]","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996682409Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4202026-03-10T22:43:51.849Z{"msg":"starting reconciliation 4a96ec85-5443-4c25-90d6-1a09a728c065: found 20 extents that need repair","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996700148Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4212026-03-10T22:43:51.849Z{"msg":"sending reconcile request ReconciliationId(2)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:50.996715367Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4222026-03-10T22:43:51.873Z{"msg":"sending reconcile request ReconciliationId(6)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.008076016Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4232026-03-10T22:43:51.873Z{"msg":"sending reconcile request ReconciliationId(10)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.010358473Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4242026-03-10T22:43:51.873Z{"msg":"sending reconcile request ReconciliationId(14)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.012568175Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4252026-03-10T22:43:51.873Z{"msg":"sending reconcile request ReconciliationId(18)","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.014626548Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4262026-03-10T22:43:51.873Z{"msg":"done with reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.016575177Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"":"downstairs","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4272026-03-10T22:43:51.873Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.016603745Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"0","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4282026-03-10T22:43:51.873Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.016620014Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"1","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4292026-03-10T22:43:51.873Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.016635113Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"client":"2","":"downstairs","session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4302026-03-10T22:43:51.873Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.016650242Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4312026-03-10T22:43:51.873Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.016664751Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4322026-03-10T22:43:51.873Z{"msg":"1ffa9f99-fc3f-48c9-9a9e-ed1756c55b6f is now active with session: 5ccaffef-beb0-488e-9ce0-0ad77bad74f1","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.0166811Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252,"session_id":"5ccaffef-beb0-488e-9ce0-0ad77bad74f1"}
4332026-03-10T22:43:51.873Z{"msg":"The guest has finished waiting for activation with:33","v":0,"name":"Wait for a query_work_queue command to finish before sending IO
4342026-03-10T22:43:51.873Zcrucible","level":30,"time":"2026-03-10T22:43:51.016704908Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252}
4352026-03-10T22:43:51.873Z{"msg":"Activated sub_volume 1ffa9f99-fc3f-48c9-9a9e-ed1756c55b6f","v":0,"name":"crucible","level":30,"time":"2026-03-10T22:43:51.016717468Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252}
4362026-03-10T22:43:51.873ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
4372026-03-10T22:43:51.873ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
4382026-03-10T22:43:51.873ZRead and Verify all blocks (0..50 range:true)
4392026-03-10T22:43:51.898ZWrote out file "/var/tmp/test_up-build/verify_file"
4402026-03-10T22:43:51.898ZVerify test completed
4412026-03-10T22:43:51.902ZWrote out file "/var/tmp/test_up-build/verify_file"
4422026-03-10T22:43:51.902ZCLIENT: Tests done. All submitted work has been ACK'd
4432026-03-10T22:43:51.902Z----------------------------------------------------------------
4442026-03-10T22:43:51.902Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:1
4452026-03-10T22:43:51.902ZStates: Active Active Active
4462026-03-10T22:43:51.902ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
4472026-03-10T22:43:51.902Z 1000 Acked Read 50 Done Done Done false
4482026-03-10T22:43:51.902Z STATES DS:0 DS:1 DS:2 TOTAL
4492026-03-10T22:43:51.902Z Sent 0 0 0 0
4502026-03-10T22:43:51.902Z Done 1 1 1 3
4512026-03-10T22:43:51.902Z Skipped 0 0 0 0
4522026-03-10T22:43:51.902Z Error 0 0 0 0
4532026-03-10T22:43:51.902ZLast Flush: None None None
4542026-03-10T22:43:51.902ZDownstairs last five completed:
4552026-03-10T22:43:51.902ZUpstairs last five completed: 1000
4562026-03-10T22:43:51.902ZCLIENT: Up:0 ds:1 act:3
4572026-03-10T22:43:55.901Z----------------------------------------------------------------
4582026-03-10T22:43:55.901Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:0
4592026-03-10T22:43:55.901ZDownstairs last five completed: 1001 1000
4602026-03-10T22:43:55.901ZUpstairs last five completed: 1001 1000
4612026-03-10T22:43:55.901ZCLIENT: Up:0 ds:0 act:3
4622026-03-10T22:43:55.901ZCLIENT: All crucible jobs finished, exiting program
4632026-03-10T22:43:55.905Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2026-03-10T22:43:55.054251267Z","hostname":"w-01KKCYES20RG4Y62MWJVSGMC3D","pid":1252}
4642026-03-10T22:43:55.908ZRepair part 2 passed
4652026-03-10T22:43:55.908Z/var/tmp/bins/crucible-downstairs dump --no-color -d /var/tmp/test_up-build/8810 -d /var/tmp/test_up-build/8820 -d /var/tmp/test_up-build/8830
4662026-03-10T22:43:55.920ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
4672026-03-10T22:43:55.921Z 0 000-009 32 32 32 1501 1501 1501 F F F
4682026-03-10T22:43:55.921Z 1 010-019 32 32 32 1501 1501 1501 F F F
4692026-03-10T22:43:55.921Z 2 020-029 32 32 32 1501 1501 1501 F F F
4702026-03-10T22:43:55.924Z 3 030-039 32 32 32 1501 1501 1501 F F F
4712026-03-10T22:43:55.924Z 4 040-049 32 32 32 1501 1501 1501 F F F
4722026-03-10T22:43:55.924ZMax gen: 32, Max flush: 1501
4732026-03-10T22:43:55.924Zdump test passed
4742026-03-10T22:43:55.924Z/var/tmp/bins/crucible-downstairs dump --no-color -d /var/tmp/test_up-build/8810 -d /var/tmp/test_up-build/8820 -d /var/tmp/test_up-build/8830 -e 1
4752026-03-10T22:43:55.936Z Extent 1
4762026-03-10T22:43:55.940ZGEN 32 32 32
4772026-03-10T22:43:55.940ZFLUSH_ID 1501 1501 1501
4782026-03-10T22:43:55.940ZDIRTY
4792026-03-10T22:43:55.940Z
4802026-03-10T22:43:55.940ZBLOCK D0 D1 D2 C0 C1 C2 DIFF
4812026-03-10T22:43:55.940Z010 A A A A A A
4822026-03-10T22:43:55.940Z011 A A A A A A
4832026-03-10T22:43:55.940Z012 A A A A A A
4842026-03-10T22:43:55.940Z013 A A A A A A
4852026-03-10T22:43:55.944Z014 A A A A A A
4862026-03-10T22:43:55.944Z015 A A A A A A
4872026-03-10T22:43:55.944Z016 A A A A A A
4882026-03-10T22:43:55.944Z017 A A A A A A
4892026-03-10T22:43:55.944Z018 A A A A A A
4902026-03-10T22:43:55.944Z019 A A A A A A
4912026-03-10T22:43:55.947Zdump extent test passed
4922026-03-10T22:43:55.947Z/var/tmp/bins/crucible-downstairs dump --no-color -d /var/tmp/test_up-build/8810 -d /var/tmp/test_up-build/8820 -d /var/tmp/test_up-build/8830 -b 20
4932026-03-10T22:43:55.959ZExtent 2 Block in extent 0 Actual block 20
4942026-03-10T22:43:55.962Z
4952026-03-10T22:43:55.962Z DATA SHA256 VER
4962026-03-10T22:43:55.962Z------ ---------------------------------------------------------------- ---
4972026-03-10T22:43:55.962Z 0 a8d4600a801f7266efd2ec567f7b8a95d5f1d31d1813fc1bd97eec0de70322c8 A
4982026-03-10T22:43:55.962Z 1 a8d4600a801f7266efd2ec567f7b8a95d5f1d31d1813fc1bd97eec0de70322c8 A
4992026-03-10T22:43:55.962Z 2 a8d4600a801f7266efd2ec567f7b8a95d5f1d31d1813fc1bd97eec0de70322c8 A
5002026-03-10T22:43:55.962Z
5012026-03-10T22:43:55.962ZNONCES 0 1 2 DIFF
5022026-03-10T22:43:55.962Z------ ------------------------ ------------------------ ------------------------ -----
5032026-03-10T22:43:55.962Z 0 b7167034ea6d907d185e2dd0 b7167034ea6d907d185e2dd0 b7167034ea6d907d185e2dd0
5042026-03-10T22:43:55.962Z
5052026-03-10T22:43:55.962Z TAGS 0 1 2 DIFF
5062026-03-10T22:43:55.962Z------ -------------------------------- -------------------------------- -------------------------------- -----
5072026-03-10T22:43:55.962Z 0 4cdc9127580229d7ab43e376a0d6ac9a 4cdc9127580229d7ab43e376a0d6ac9a 4cdc9127580229d7ab43e376a0d6ac9a
5082026-03-10T22:43:55.962Z
5092026-03-10T22:43:55.963ZHASHES 0 1 2 DIFF
5102026-03-10T22:43:55.963Z------ ---------------- ---------------- ---------------- -----
5112026-03-10T22:43:55.963Z
5122026-03-10T22:43:55.966Zdump block test passed
5132026-03-10T22:43:55.966ZInitial upstairs tests have completed, stopping all downstairs
5142026-03-10T22:44:00.990ZCreating 4 larger downstairs regions
5152026-03-10T22:44:01.139ZStarting 4 downstairs
5162026-03-10T22:44:06.146Zdsc restarted at PID: 1265
5172026-03-10T22:44:06.225ZNow do the replace-reconcile test
5182026-03-10T22:44:06.243ZUsing 8840 for the replacement port
5192026-03-10T22:47:42.705ZCompleted test: replace-reconcile
5202026-03-10T22:47:42.709ZNow do the replace-before-active test
5212026-03-10T22:51:16.182ZCompleted test: replace-before-active
5222026-03-10T22:51:16.182ZAll tests have completed, stopping all downstairs
5232026-03-10T22:51:16.203Z
5242026-03-10T22:51:16.203ZAll Tests have passed
5252026-03-10T22:51:16.206Z10:11 Test duration
5262026-03-10T22:51:16.206Z
5272026-03-10T22:51:16.206Zreal 10:10.989287136
5282026-03-10T22:51:16.206Zuser 9:57.192093823
5292026-03-10T22:51:16.206Zsys 7.974874475
5302026-03-10T22:51:16.206Ztrap 0.273460398
5312026-03-10T22:51:16.206Ztflt 0.028352298
5322026-03-10T22:51:16.206Zdflt 0.011697905
5332026-03-10T22:51:16.206Zkflt 0.001041848
5342026-03-10T22:51:16.206Zlock 7:05:50.639419068
5352026-03-10T22:51:16.207Zslp 31:01.360293495
5362026-03-10T22:51:16.207Zlat 50.806528393
5372026-03-10T22:51:16.207Zstop 0.010390952
5382026-03-10T22:51:16.207Z+ echo 'test-up-encrypted ends'
5392026-03-10T22:51:16.207Ztest-up-encrypted ends
5402026-03-10T22:51:21.208Zprocess exited: duration 621134 ms, exit code 0
5412026-03-10T22:51:21.208Zexec warning: : stdio descriptors remain open after task exit; waiting 60 seconds for them to close
5422026-03-10T22:52:21.242Zexec warning: : stdout descriptor may be held open by a background process; giving up!
5432026-03-10T22:52:21.242Zexec warning: : stderr descriptor may be held open by a background process; giving up!
 
5442026-03-10T22:52:21.254Zfound 14 output files
5452026-03-10T22:52:21.254Zuploading: /tmp/test_up-build/dsc-out.txt (47189 bytes)
5462026-03-10T22:52:22.268Zuploaded: /tmp/test_up-build/dsc-out.txt
5472026-03-10T22:52:22.277Zuploading: /tmp/test_up-build/test_up_out.txt (22485892 bytes)
5482026-03-10T22:52:23.527Zuploaded: /tmp/test_up-build/test_up_out.txt
5492026-03-10T22:52:23.530Zuploading: /tmp/test_up-build/dsc/downstairs-8810.txt (981717 bytes)
5502026-03-10T22:52:24.559Zuploaded: /tmp/test_up-build/dsc/downstairs-8810.txt
5512026-03-10T22:52:24.567Zuploading: /tmp/test_up-build/dsc/downstairs-8820.txt (548347 bytes)
5522026-03-10T22:52:25.612Zuploaded: /tmp/test_up-build/dsc/downstairs-8820.txt
5532026-03-10T22:52:25.612Zuploading: /tmp/test_up-build/dsc/downstairs-8830.txt (979049 bytes)
5542026-03-10T22:52:26.634Zuploaded: /tmp/test_up-build/dsc/downstairs-8830.txt
5552026-03-10T22:52:26.634Zuploading: /tmp/test_up-build/dsc/downstairs-8840.txt (543000 bytes)
5562026-03-10T22:52:27.655Zuploaded: /tmp/test_up-build/dsc/downstairs-8840.txt
5572026-03-10T22:52:27.655Zuploading: /tmp/debug/df.txt (1270 bytes)
5582026-03-10T22:52:28.663Zuploaded: /tmp/debug/df.txt
5592026-03-10T22:52:28.667Zuploading: /tmp/debug/dtrace.txt (636998 bytes)
5602026-03-10T22:52:29.685Zuploaded: /tmp/debug/dtrace.txt
5612026-03-10T22:52:29.685Zuploading: /tmp/debug/iostat.txt (201904 bytes)
5622026-03-10T22:52:29.696Zupload warning: file "/tmp/debug/iostat.txt" changed size mid upload: 201904 -> 204288
5632026-03-10T22:52:30.703Zuploaded: /tmp/debug/iostat.txt
5642026-03-10T22:52:30.706Zuploading: /tmp/debug/mpstat.txt (492346 bytes)
5652026-03-10T22:52:30.717Zupload warning: file "/tmp/debug/mpstat.txt" changed size mid upload: 492346 -> 498889
5662026-03-10T22:52:31.724Zuploaded: /tmp/debug/mpstat.txt
5672026-03-10T22:52:31.727Zuploading: /tmp/debug/paging.txt (87245 bytes)
5682026-03-10T22:52:31.732Zupload warning: file "/tmp/debug/paging.txt" changed size mid upload: 87245 -> 88533
5692026-03-10T22:52:32.738Zuploaded: /tmp/debug/paging.txt
5702026-03-10T22:52:32.738Zuploading: /tmp/debug/prstat.txt (956658 bytes)
5712026-03-10T22:52:32.758Zupload warning: file "/tmp/debug/prstat.txt" changed size mid upload: 956658 -> 972133
5722026-03-10T22:52:33.764Zuploaded: /tmp/debug/prstat.txt
5732026-03-10T22:52:33.764Zuploading: /tmp/debug/psrinfo.txt (1528 bytes)
5742026-03-10T22:52:34.773Zuploaded: /tmp/debug/psrinfo.txt
5752026-03-10T22:52:34.776Zuploading: /tmp/debug/upstairs-info.txt (78183 bytes)
5762026-03-10T22:52:35.787Zuploaded: /tmp/debug/upstairs-info.txt