01KBHG84DJM5T7R9HXCJZRP5RR: test-up-unencrypted

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: 01KBHG8EWX7N528WB315Q8YV0E

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-12-03T07:20:35.164Zjob dependencies complete; ready to run (waiting for 18 m 58 s)
22025-12-03T07:21:36.349Zjob assigned to worker 01KBHHBAC3N5G1974Q74SJ2B4D [factory aws, i-04bc3f3ff03848663] (queued for 1 m 1 s)
32025-12-03T07:21:44.485Zdownloading input: /input/build/work/bins/crucible-downstairs.gz
42025-12-03T07:21:46.089Zdownloaded input: /input/build/work/bins/crucible-downstairs.gz
52025-12-03T07:21:46.089Zdownloading input: /input/build/work/bins/crucible-hammer.gz
62025-12-03T07:21:47.628Zdownloaded input: /input/build/work/bins/crucible-hammer.gz
72025-12-03T07:21:47.628Zdownloading input: /input/build/work/bins/crutest.gz
82025-12-03T07:21:49.089Zdownloaded input: /input/build/work/bins/crutest.gz
92025-12-03T07:21:49.090Zdownloading input: /input/build/work/bins/dsc.gz
102025-12-03T07:21:49.842Zdownloaded input: /input/build/work/bins/dsc.gz
112025-12-03T07:21:49.846Zdownloading input: /input/build/work/scripts/perf-downstairs-tick.d
122025-12-03T07:21:49.862Zdownloaded input: /input/build/work/scripts/perf-downstairs-tick.d
132025-12-03T07:21:49.862Zdownloading input: /input/build/work/scripts/test_ds.sh
142025-12-03T07:21:49.906Zdownloaded input: /input/build/work/scripts/test_ds.sh
152025-12-03T07:21:49.906Zdownloading input: /input/build/work/scripts/test_live_repair.sh
162025-12-03T07:21:49.930Zdownloaded input: /input/build/work/scripts/test_live_repair.sh
172025-12-03T07:21:49.930Zdownloading input: /input/build/work/scripts/test_repair.sh
182025-12-03T07:21:49.951Zdownloaded input: /input/build/work/scripts/test_repair.sh
192025-12-03T07:21:49.951Zdownloading input: /input/build/work/scripts/test_replay.sh
202025-12-03T07:21:49.973Zdownloaded input: /input/build/work/scripts/test_replay.sh
212025-12-03T07:21:49.973Zdownloading input: /input/build/work/scripts/test_up.sh
222025-12-03T07:21:49.992Zdownloaded input: /input/build/work/scripts/test_up.sh
232025-12-03T07:21:49.992Zdownloading input: /input/build/work/scripts/upstairs_info.d
242025-12-03T07:21:50.011Zdownloaded input: /input/build/work/scripts/upstairs_info.d
252025-12-03T07:21:50.015Zdownloading input: /input/build/tmp/cargo-test-out.log
262025-12-03T07:21:50.543Zdownloaded input: /input/build/tmp/cargo-test-out.log
 
272025-12-03T07:21:50.543Zstarting task 0: "setup"
282025-12-03T07:21:50.551Z++ uname -s
292025-12-03T07:21:50.554Z+ kern=SunOS
302025-12-03T07:21:50.554Z+ build_user=build
312025-12-03T07:21:50.554Z+ build_uid=12345
322025-12-03T07:21:50.554Z+ work_dir=/work
332025-12-03T07:21:50.554Z+ input_dir=/input
342025-12-03T07:21:50.554Z+ [[ 0 == 12345 ]]
352025-12-03T07:21:50.554Z+ case "$kern" in
362025-12-03T07:21:50.554Z+ groupadd -g 12345 build
372025-12-03T07:21:50.557Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
382025-12-03T07:21:52.564Z+ zfs create -o mountpoint=/work rpool/work
392025-12-03T07:21:52.914Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
402025-12-03T07:21:52.918Z+ home_fs=zfs
412025-12-03T07:21:52.918Z+ [[ zfs == autofs ]]
422025-12-03T07:21:52.918Z+ mkdir -p /home/build
432025-12-03T07:21:52.921Z+ chown build:build /home/build /work
442025-12-03T07:21:54.921Z+ chmod 0700 /home/build /work
452025-12-03T07:21:54.924Zprocess exited: duration 4380 ms, exit code 0
 
462025-12-03T07:21:54.933Zstarting task 1: "authentication"
472025-12-03T07:21:54.952Zprocess exited: duration 21 ms, exit code 0
 
482025-12-03T07:21:54.960Zstarting task 2: "build"
492025-12-03T07:21:54.963Z+ banner cores
502025-12-03T07:21:54.966Z
512025-12-03T07:21:54.966Z #### #### ##### ###### ####
522025-12-03T07:21:54.966Z # # # # # # # #
532025-12-03T07:21:54.966Z # # # # # ##### ####
542025-12-03T07:21:54.966Z # # # ##### # #
552025-12-03T07:21:54.966Z # # # # # # # # #
562025-12-03T07:21:54.966Z #### #### # # ###### ####
572025-12-03T07:21:54.966Z
582025-12-03T07:21:54.966Z+ pfexec coreadm -i /tmp/core.%f.%p -g /tmp/core.%f.%p -e global -e log -e proc-setid -e global-setid
592025-12-03T07:21:54.975Z+ echo 'input bins dir contains:'
602025-12-03T07:21:54.975Zinput bins dir contains:
612025-12-03T07:21:54.979Z+ ls -ltr /input/build/work/bins
622025-12-03T07:21:54.979Ztotal 971674
632025-12-03T07:21:54.979Z-rw-r--r-- 1 root root 144748253 Dec 3 07:21 crucible-downstairs.gz
642025-12-03T07:21:54.979Z-rw-r--r-- 1 root root 137729702 Dec 3 07:21 crucible-hammer.gz
652025-12-03T07:21:54.979Z-rw-r--r-- 1 root root 143016065 Dec 3 07:21 crutest.gz
662025-12-03T07:21:54.979Z-rw-r--r-- 1 root root 71676398 Dec 3 07:21 dsc.gz
672025-12-03T07:21:54.979Z+ banner unpack
682025-12-03T07:21:54.982Z
692025-12-03T07:21:54.982Z # # # # ##### ## #### # #
702025-12-03T07:21:54.982Z # # ## # # # # # # # # #
712025-12-03T07:21:54.982Z # # # # # # # # # # ####
722025-12-03T07:21:54.982Z # # # # # ##### ###### # # #
732025-12-03T07:21:54.982Z # # # ## # # # # # # #
742025-12-03T07:21:54.982Z #### # # # # # #### # #
752025-12-03T07:21:54.982Z
762025-12-03T07:21:54.982Z+ mkdir -p /var/tmp/bins
772025-12-03T07:21:54.982Z+ for t in "$input/bins/"*.gz
782025-12-03T07:21:54.985Z++ basename /input/build/work/bins/crucible-downstairs.gz
792025-12-03T07:21:54.985Z+ b=crucible-downstairs.gz
802025-12-03T07:21:54.985Z+ b=crucible-downstairs
812025-12-03T07:21:54.985Z+ gunzip
822025-12-03T07:21:57.994Z+ chmod +x /var/tmp/bins/crucible-downstairs
832025-12-03T07:21:57.997Z+ for t in "$input/bins/"*.gz
842025-12-03T07:21:58.002Z++ basename /input/build/work/bins/crucible-hammer.gz
852025-12-03T07:21:58.002Z+ b=crucible-hammer.gz
862025-12-03T07:21:58.002Z+ b=crucible-hammer
872025-12-03T07:21:58.002Z+ gunzip
882025-12-03T07:22:00.822Z+ chmod +x /var/tmp/bins/crucible-hammer
892025-12-03T07:22:00.825Z+ for t in "$input/bins/"*.gz
902025-12-03T07:22:00.825Z++ basename /input/build/work/bins/crutest.gz
912025-12-03T07:22:00.828Z+ b=crutest.gz
922025-12-03T07:22:00.828Z+ b=crutest
932025-12-03T07:22:00.828Z+ gunzip
942025-12-03T07:22:03.809Z+ chmod +x /var/tmp/bins/crutest
952025-12-03T07:22:03.812Z+ for t in "$input/bins/"*.gz
962025-12-03T07:22:03.812Z++ basename /input/build/work/bins/dsc.gz
972025-12-03T07:22:03.815Z+ b=dsc.gz
982025-12-03T07:22:03.815Z+ b=dsc
992025-12-03T07:22:03.815Z+ gunzip
1002025-12-03T07:22:05.285Z+ chmod +x /var/tmp/bins/dsc
1012025-12-03T07:22:05.289Z+ export BINDIR=/var/tmp/bins
1022025-12-03T07:22:05.289Z+ BINDIR=/var/tmp/bins
1032025-12-03T07:22:05.289Z+ export RUST_BACKTRACE=1
1042025-12-03T07:22:05.289Z+ RUST_BACKTRACE=1
1052025-12-03T07:22:05.289Z+ jobpid=1157
1062025-12-03T07:22:05.289Z+ echo 'Setup debug logging'
1072025-12-03T07:22:05.289ZSetup debug logging
1082025-12-03T07:22:05.289Z+ mkdir /tmp/debug
1092025-12-03T07:22:05.289Z+ sleep 7200
1102025-12-03T07:22:05.293Z+ psrinfo -v
1112025-12-03T07:22:05.296Z+ df -h
1122025-12-03T07:22:05.301Z+ prstat -d d -mLc 1
1132025-12-03T07:22:05.304Z+ iostat -T d -xn 1
1142025-12-03T07:22:05.304Z+ mpstat -T d 1
1152025-12-03T07:22:05.304Z+ vmstat -T d -p 1
1162025-12-03T07:22:05.304Z+ pfexec dtrace -Z -s /input/build/work/scripts/perf-downstairs-tick.d
1172025-12-03T07:22:05.308Z+ banner test_up_unencrypted
1182025-12-03T07:22:05.308Z+ pfexec dtrace -Z -s /input/build/work/scripts/upstairs_info.d
1192025-12-03T07:22:05.308Z
1202025-12-03T07:22:05.308Z ##### ###### #### ##### # # ##### # # # #
1212025-12-03T07:22:05.308Z # # # # # # # # # # ## #
1222025-12-03T07:22:05.308Z # ##### #### # # # # # # # # # #
1232025-12-03T07:22:05.308Z # # # # # # ##### # # # # #
1242025-12-03T07:22:05.308Z # # # # # # # # # # # ##
1252025-12-03T07:22:05.308Z # ###### #### # ####### #### # ####### #### # #
1262025-12-03T07:22:05.308Z
1272025-12-03T07:22:05.308Z+ ptime -m bash /input/build/work/scripts/test_up.sh -N unencrypted
1282025-12-03T07:22:05.319Z/input/build/work
1292025-12-03T07:22:05.330ZTurn off color for downstairs dump
1302025-12-03T07:22:05.333Zdsc output goes to /tmp/test_up-build/dsc-out.txt
1312025-12-03T07:22:05.333ZCreating 3 downstairs regions
1322025-12-03T07:22:05.673ZStarting 3 downstairs
1332025-12-03T07:22:05.677Zdsc started at PID: 1202
1342025-12-03T07:22:10.855ZDisable automatic restart on all downstairs
1352025-12-03T07:22:10.909Z
1362025-12-03T07:22:10.909ZBegin tests, output goes to /tmp/test_up-build/test_up_out.txt
1372025-12-03T07:22:10.912ZRunning test: span
1382025-12-03T07:22:15.045ZCompleted test: span
1392025-12-03T07:22:20.053ZRunning test: big
1402025-12-03T07:22:24.197ZCompleted test: big
1412025-12-03T07:22:29.205ZRunning test: dep
1422025-12-03T07:22:42.012ZCompleted test: dep
1432025-12-03T07:22:47.019ZRunning test: balloon
1442025-12-03T07:22:56.598ZCompleted test: balloon
1452025-12-03T07:23:01.606ZRunning test: deactivate
1462025-12-03T07:23:05.810ZCompleted test: deactivate
1472025-12-03T07:23:10.819ZRunning hammer
1482025-12-03T07:23:13.720ZRun repair tests
1492025-12-03T07:23:13.723Z/var/tmp/bins/crutest fill -g 31 -q --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file
1502025-12-03T07:23:13.782Z{"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":"2025-12-03T07:23:13.358024827Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"task":"crutest"}
1512025-12-03T07:23:13.786Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.358648877Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"task":"crutest"}
1522025-12-03T07:23:13.786Z{"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":"2025-12-03T07:23:13.360532506Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"task":"crutest"}
1532025-12-03T07:23:13.786Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.360837602Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239}
1542025-12-03T07:23:13.786Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"2882d8b71cde865f6d2a2d0554debbccaa9eae34\",\n git_commit_timestamp: \"2025-12-03T07:01:06.000000000Z\",\n git_branch: \"renovate/actions-checkout-digest\",\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":"2025-12-03T07:23:13.360889193Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239}
1552025-12-03T07:23:13.786Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.360913408Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239}
1562025-12-03T07:23:13.786Z{"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: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.360936134Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239}
1572025-12-03T07:23:13.786Z{"msg":"Crucible ab5e5637-ab01-4298-b6b4-bf13ce2b1161 has session id: a848f44f-2df3-47db-bbc5-f5815434926c","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.361385685Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1582025-12-03T07:23:13.786Z{"msg":"Upstairs opts: Upstairs UUID: ab5e5637-ab01-4298-b6b4-bf13ce2b1161, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, 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":"2025-12-03T07:23:13.361466101Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1592025-12-03T07:23:13.786Z{"msg":"Crucible stats registered with UUID: ab5e5637-ab01-4298-b6b4-bf13ce2b1161","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.361516662Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1602025-12-03T07:23:13.786Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-12-03T07:23:13.361535229Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1612025-12-03T07:23:13.790Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.361807201Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"io task","client":"0","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1622025-12-03T07:23:13.790Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.361875159Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"io task","client":"1","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1632025-12-03T07:23:13.790Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.361921851Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"io task","client":"2","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1642025-12-03T07:23:13.790Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.36255301Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"task":"crutest"}
1652025-12-03T07:23:13.790Z{"msg":"The guest has requested activation with gen:31","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362594023Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239}
1662025-12-03T07:23:13.790Z{"msg":"ab5e5637-ab01-4298-b6b4-bf13ce2b1161 active request set","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362624647Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1672025-12-03T07:23:13.790Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362659811Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"client":"0","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1682025-12-03T07:23:13.790Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362690835Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"client":"1","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1692025-12-03T07:23:13.790Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362718301Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"client":"2","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1702025-12-03T07:23:13.791Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362746016Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"io task","client":"2","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1712025-12-03T07:23:13.791Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362781179Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"io task","client":"0","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1722025-12-03T07:23:13.791Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362819933Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"io task","client":"1","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1732025-12-03T07:23:13.791Z{"msg":"ds_connection connected from Ok(127.0.0.1:41360)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362905597Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"io task","client":"1","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1742025-12-03T07:23:13.791Z{"msg":"ds_connection connected from Ok(127.0.0.1:36044)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362954849Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"io task","client":"0","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1752025-12-03T07:23:13.791Z{"msg":"ds_connection connected from Ok(127.0.0.1:60849)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.362994982Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"io task","client":"2","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1762025-12-03T07:23:13.791Z{"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":"2025-12-03T07:23:13.364214847Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"client":"0","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1772025-12-03T07:23:13.791Z{"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":"2025-12-03T07:23:13.364257719Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"client":"1","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1782025-12-03T07:23:13.791Z{"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":"2025-12-03T07:23:13.364289304Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"client":"2","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1792025-12-03T07:23:13.791Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.36459673Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1802025-12-03T07:23:13.791Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.364734515Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1812025-12-03T07:23:13.791Z{"msg":"[0]R flush_numbers: [1495, 1495, 1495, 1495, 1495]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.364816301Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1822025-12-03T07:23:13.791Z{"msg":"[0]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.364856604Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1832025-12-03T07:23:13.791Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.364882849Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1842025-12-03T07:23:13.791Z{"msg":"[1]R flush_numbers: [1495, 1495, 1495, 1495, 1495]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.364913224Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1852025-12-03T07:23:13.791Z{"msg":"[1]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.36493801Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1862025-12-03T07:23:13.791Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.364956696Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1872025-12-03T07:23:13.791Z{"msg":"[2]R flush_numbers: [1495, 1495, 1495, 1495, 1495]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.364981342Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1882025-12-03T07:23:13.791Z{"msg":"[2]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365002348Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1892025-12-03T07:23:13.791Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365036812Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1902025-12-03T07:23:13.791Z{"msg":Wait for a query_work_queue command to finish before sending IO
1912025-12-03T07:23:13.791Z"Max found gen is 26","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365069487Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1922025-12-03T07:23:13.791Z{"msg":"Generation requested: 31 >= found:26","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365086773Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1932025-12-03T07:23:13.791Z{"msg":"Next flush: 1496","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365102921Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1942025-12-03T07:23:13.791Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365126497Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"":"downstairs","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1952025-12-03T07:23:13.791Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365144053Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1962025-12-03T07:23:13.791Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365165679Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"client":"0","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1972025-12-03T07:23:13.791Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365182756Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"client":"1","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1982025-12-03T07:23:13.791Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365205592Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"client":"2","":"downstairs","session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
1992025-12-03T07:23:13.791Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.3652226Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
2002025-12-03T07:23:13.791Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365245016Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
2012025-12-03T07:23:13.791Z{"msg":"ab5e5637-ab01-4298-b6b4-bf13ce2b1161 is now active with session: a848f44f-2df3-47db-bbc5-f5815434926c","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365263242Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
2022025-12-03T07:23:13.791Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365284859Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239,"session_id":"a848f44f-2df3-47db-bbc5-f5815434926c"}
2032025-12-03T07:23:13.791Z{"msg":"The guest has finished waiting for activation with:31","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365300916Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239}
2042025-12-03T07:23:13.791Z{"Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2052025-12-03T07:23:13.791Zmsg":"Activated sub_volume ab5e5637-ab01-4298-b6b4-bf13ce2b1161","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:13.365324082Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1239}
2062025-12-03T07:23:13.791ZFill test
2072025-12-03T07:23:13.806ZRead and Verify all blocks (0..50 range:false)
2082025-12-03T07:23:13.806ZWrote out file "/var/tmp/test_up-build/verify_file"
2092025-12-03T07:23:13.806ZCLIENT: Tests done. All submitted work has been ACK'd
2102025-12-03T07:23:13.807Z----------------------------------------------------------------
2112025-12-03T07:23:13.807Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:1
2122025-12-03T07:23:13.807ZStates: Active Active Active
2132025-12-03T07:23:13.807ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2142025-12-03T07:23:13.807Z 1002 Acked Read 50 Done Done Done false
2152025-12-03T07:23:13.807Z STATES DS:0 DS:1 DS:2 TOTAL
2162025-12-03T07:23:13.807Z Sent 0 0 0 0
2172025-12-03T07:23:13.807Z Done 1 1 1 3
2182025-12-03T07:23:13.807Z Skipped 0 0 0 0
2192025-12-03T07:23:13.807Z Error 0 0 0 0
2202025-12-03T07:23:13.807ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
2212025-12-03T07:23:13.807ZDownstairs last five completed: 1001 1000
2222025-12-03T07:23:13.807ZUpstairs last five completed: 1002 1001 1000
2232025-12-03T07:23:13.807ZCLIENT: Up:0 ds:1 act:3
2242025-12-03T07:23:17.804Z----------------------------------------------------------------
2252025-12-03T07:23:17.804Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:0
2262025-12-03T07:23:17.804ZDownstairs last five completed: 1003 1002 1001 1000
2272025-12-03T07:23:17.804ZUpstairs last five completed: 1003 1002 1001 1000
2282025-12-03T07:23:17.804ZCLIENT: Up:0 ds:0 act:3
2292025-12-03T07:23:17.804ZCLIENT: All crucible jobs finished, exiting program
2302025-12-03T07:23:17.816ZRepair setup passed
2312025-12-03T07:23:17.819ZCopy the region for /var/tmp/test_up-build/8830
2322025-12-03T07:23:17.819Zcp -r /var/tmp/test_up-build/8830 /var/tmp/test_up-build/previous
2332025-12-03T07:23:17.822Z/var/tmp/bins/crutest fill -g 32 -q --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
2342025-12-03T07:23:17.880Z{"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":"2025-12-03T07:23:17.454933106Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"task":"crutest"}
2352025-12-03T07:23:17.883Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.45553297Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"task":"crutest"}
2362025-12-03T07:23:17.883Z{"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":"2025-12-03T07:23:17.457397552Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"task":"crutest"}
2372025-12-03T07:23:17.884Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.457712246Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245}
2382025-12-03T07:23:17.884Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"2882d8b71cde865f6d2a2d0554debbccaa9eae34\",\n git_commit_timestamp: \"2025-12-03T07:01:06.000000000Z\",\n git_branch: \"renovate/actions-checkout-digest\",\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":"2025-12-03T07:23:17.457786864Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245}
2392025-12-03T07:23:17.884Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.457822207Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245}
2402025-12-03T07:23:17.884Z{"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: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.457872968Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245}
2412025-12-03T07:23:17.884Z{"msg":"Crucible 0a2e5c57-338a-4cb9-bee5-10bf654e594a has session id: 36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.458348865Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2422025-12-03T07:23:17.884Z{"msg":"Upstairs opts: Upstairs UUID: 0a2e5c57-338a-4cb9-bee5-10bf654e594a, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, 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":"2025-12-03T07:23:17.458421152Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2432025-12-03T07:23:17.884Z{"msg":"Crucible stats registered with UUID: 0a2e5c57-338a-4cb9-bee5-10bf654e594a","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.458460865Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2442025-12-03T07:23:17.884Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-12-03T07:23:17.458503387Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2452025-12-03T07:23:17.884Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.458594281Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"io task","client":"1","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2462025-12-03T07:23:17.884Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.458649381Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"io task","client":"0","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2472025-12-03T07:23:17.884Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.458695033Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"io task","client":"2","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2482025-12-03T07:23:17.889Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.459314435Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"task":"crutest"}
2492025-12-03T07:23:17.889Z{"msg":"The guest has requested activation with gen:32","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.459365775Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245}
2502025-12-03T07:23:17.889Z{"msg":"0a2e5c57-338a-4cb9-bee5-10bf654e594a active request set","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.45945052Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2512025-12-03T07:23:17.889Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.459486334Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"client":"0","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2522025-12-03T07:23:17.889Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.45950998Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"client":"1","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2532025-12-03T07:23:17.889Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.45956543Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"client":"2","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2542025-12-03T07:23:17.889Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.459602164Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"io task","client":"2","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2552025-12-03T07:23:17.889Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.459652865Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"io task","client":"0","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2562025-12-03T07:23:17.889Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.459697237Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"io task","client":"1","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2572025-12-03T07:23:17.889Z{"msg":"ds_connection connected from Ok(127.0.0.1:47097)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.459748928Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"io task","client":"2","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2582025-12-03T07:23:17.889Z{"msg":"ds_connection connected from Ok(127.0.0.1:48735)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.4597934Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"io task","client":"0","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2592025-12-03T07:23:17.889Z{"msg":"ds_connection connected from Ok(127.0.0.1:38630)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.45996261Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"io task","client":"1","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2602025-12-03T07:23:17.889Z{"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":"2025-12-03T07:23:17.46121286Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"client":"2","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2612025-12-03T07:23:17.889Z{"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":"2025-12-03T07:23:17.461246834Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"client":"1","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2622025-12-03T07:23:17.889Z{"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":"2025-12-03T07:23:17.46126915Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"client":"0","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2632025-12-03T07:23:17.889Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.461683847Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2642025-12-03T07:23:17.889Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.46172525Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2652025-12-03T07:23:17.889Z{"msg":"[0]R flush_numbers: [1496, 1496, 1496, 1496, 1496]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.461754035Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2662025-12-03T07:23:17.889Z{"msg":"[0]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.461786119Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2672025-12-03T07:23:17.889Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.461815884Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2682025-12-03T07:23:17.889Z{"msg":"[1]R flush_numbers: [1496, 1496, 1496, 1496, 1496]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.461849918Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2692025-12-03T07:23:17.889Z{"msg":"[1]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.461887331Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2702025-12-03T07:23:17.890Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.461917046Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2712025-12-03T07:23:17.890Z{"msg":"[2]R flush_numbers: [1496, 1496, 1496, 1496, 1496]","v":0,"name":"crucible","level":30,"time":Wait for a query_work_queue command to finish before sending IO
2722025-12-03T07:23:17.890Z"2025-12-03T07:23:17.46195266Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2732025-12-03T07:23:17.890Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.461990583Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2742025-12-03T07:23:17.890Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462020098Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2752025-12-03T07:23:17.890Z{"msg":"Max found gen is 32","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462049063Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2762025-12-03T07:23:17.890Z{"msg":"Generation requested: 32 >= found:32","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462085836Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2772025-12-03T07:23:17.890Z{"msg":"Next flush: 1497","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.46212241Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2782025-12-03T07:23:17.890Z"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2792025-12-03T07:23:17.890Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462155984Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"":"downstairs","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2802025-12-03T07:23:17.890Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462190908Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2812025-12-03T07:23:17.890Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462224022Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"client":"0","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2822025-12-03T07:23:17.890Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462251197Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"client":"1","":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2832025-12-03T07:23:17.890Z{"msg":"Loading write count information from file "/var/tmp/test_up-build/verify_file"
2842025-12-03T07:23:17.890ZTransition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462288311Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"client":"2"Fill test
2852025-12-03T07:23:17.890Z,"":"downstairs","session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2862025-12-03T07:23:17.890Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462319825Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2872025-12-03T07:23:17.891Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462353239Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2882025-12-03T07:23:17.891Z{"msg":"0a2e5c57-338a-4cb9-bee5-10bf654e594a is now active with session: 36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462391742Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2892025-12-03T07:23:17.891Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462425077Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245,"session_id":"36d4d1bd-43a7-4ae7-8929-8b9bd2b5d209"}
2902025-12-03T07:23:17.891Z{"msg":"The guest has finished waiting for activation with:32","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462452632Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245}
2912025-12-03T07:23:17.891Z{"msg":"Activated sub_volume 0a2e5c57-338a-4cb9-bee5-10bf654e594a","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:17.462483756Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1245}
2922025-12-03T07:23:17.895ZRead and Verify all blocks (0..50 range:false)
2932025-12-03T07:23:17.899ZWrote out file "/var/tmp/test_up-build/verify_file"
2942025-12-03T07:23:17.899ZCLIENT: Tests done. All submitted work has been ACK'd
2952025-12-03T07:23:17.902Z----------------------------------------------------------------
2962025-12-03T07:23:17.903Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:1
2972025-12-03T07:23:17.903ZStates: Active Active Active
2982025-12-03T07:23:17.903ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2992025-12-03T07:23:17.903Z 1002 Acked Read 50 Done Done Done false
3002025-12-03T07:23:17.903Z STATES DS:0 DS:1 DS:2 TOTAL
3012025-12-03T07:23:17.903Z Sent 0 0 0 0
3022025-12-03T07:23:17.903Z Done 1 1 1 3
3032025-12-03T07:23:17.903Z Skipped 0 0 0 0
3042025-12-03T07:23:17.903Z Error 0 0 0 0
3052025-12-03T07:23:17.903ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
3062025-12-03T07:23:17.903ZDownstairs last five completed: 1001 1000
3072025-12-03T07:23:17.903ZUpstairs last five completed: 1002 1001 1000
3082025-12-03T07:23:17.903ZCLIENT: Up:0 ds:1 act:3
3092025-12-03T07:23:21.902Z----------------------------------------------------------------
3102025-12-03T07:23:21.902Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:0
3112025-12-03T07:23:21.902ZDownstairs last five completed: 1003 1002 1001 1000
3122025-12-03T07:23:21.902ZUpstairs last five completed: 1003 1002 1001 1000
3132025-12-03T07:23:21.902ZCLIENT: Up:0 ds:0 act:3
3142025-12-03T07:23:21.905ZCLIENT: All crucible jobs finished, exiting program
3152025-12-03T07:23:21.914ZRepair part 1 passed
3162025-12-03T07:23:21.914Z
3172025-12-03T07:23:21.914ZKill the current downstairs
3182025-12-03T07:23:22.075ZDownstairs 2 stopped
3192025-12-03T07:23:22.075Zmv /var/tmp/test_up-build/8830 /var/tmp/test_up-build/new
3202025-12-03T07:23:22.078ZNow put back the original so we have a mismatch
3212025-12-03T07:23:22.078Zmv /var/tmp/test_up-build/previous /var/tmp/test_up-build/8830
3222025-12-03T07:23:22.081ZRestart downstairs with old directory
3232025-12-03T07:23:22.136Z/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
3242025-12-03T07:23:22.153ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
3252025-12-03T07:23:22.157Z 0 000-009 32 32 31 1497 1497 1496 F F F <---
3262025-12-03T07:23:22.157Z 1 010-019 32 32 31 1497 1497 1496 F F F <---
3272025-12-03T07:23:22.157Z 2 020-029 32 32 31 1497 1497 1496 F F F <---
3282025-12-03T07:23:22.157Z 3 030-039 32 32 31 1497 1497 1496 F F F <---
3292025-12-03T07:23:22.157Z 4 040-049 32 32 31 1497 1497 1496 F F F <---
3302025-12-03T07:23:22.157ZMax gen: 32, Max flush: 1497
3312025-12-03T07:23:22.414ZError: Difference in extent metadata found!
3322025-12-03T07:23:22.414Z
3332025-12-03T07:23:22.414ZStack backtrace:
3342025-12-03T07:23:22.414Z 0: anyhow::error::<impl anyhow::Error>::msg
3352025-12-03T07:23:22.414Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/backtrace.rs:27:14
3362025-12-03T07:23:22.414Z 1: anyhow::__private::format_err
3372025-12-03T07:23:22.414Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/lib.rs:695:13
3382025-12-03T07:23:22.432Zdump test found error as expected
3392025-12-03T07:23:22.435Z
3402025-12-03T07:23:22.435Z
3412025-12-03T07:23:22.435Z/var/tmp/bins/crutest verify --range -g 33 -q --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
3422025-12-03T07:23:22.490Z{"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":"2025-12-03T07:23:22.064188303Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"task":"crutest"}
3432025-12-03T07:23:22.493Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.064796706Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"task":"crutest"}
3442025-12-03T07:23:22.493Z{"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":"2025-12-03T07:23:22.066802273Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"task":"crutest"}
3452025-12-03T07:23:22.493Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.067192634Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253}
3462025-12-03T07:23:22.493Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"2882d8b71cde865f6d2a2d0554debbccaa9eae34\",\n git_commit_timestamp: \"2025-12-03T07:01:06.000000000Z\",\n git_branch: \"renovate/actions-checkout-digest\",\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":"2025-12-03T07:23:22.067280419Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253}
3472025-12-03T07:23:22.493Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.067356265Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253}
3482025-12-03T07:23:22.493Z{"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: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.067418184Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253}
3492025-12-03T07:23:22.497Z{"msg":"Crucible 29e49175-9c90-452c-a4bb-58fb54641bfc has session id: 782bab24-07f9-4452-973d-b47360ee807f","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.067902649Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3502025-12-03T07:23:22.497Z{"msg":"Upstairs opts: Upstairs UUID: 29e49175-9c90-452c-a4bb-58fb54641bfc, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, 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":"2025-12-03T07:23:22.067991623Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3512025-12-03T07:23:22.497Z{"msg":"Crucible stats registered with UUID: 29e49175-9c90-452c-a4bb-58fb54641bfc","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.068078128Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3522025-12-03T07:23:22.497Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-12-03T07:23:22.06812571Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3532025-12-03T07:23:22.497Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.068345091Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"0","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3542025-12-03T07:23:22.497Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.068424417Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"1","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3552025-12-03T07:23:22.497Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.068479817Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3562025-12-03T07:23:22.497Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069120915Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"task":"crutest"}
3572025-12-03T07:23:22.497Z{"msg":"The guest has requested activation with gen:33","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069150419Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253}
3582025-12-03T07:23:22.497Z{"msg":"29e49175-9c90-452c-a4bb-58fb54641bfc active request set","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069240383Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3592025-12-03T07:23:22.497Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069274737Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"0","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3602025-12-03T07:23:22.497Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069294544Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"1","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3612025-12-03T07:23:22.497Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069332097Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3622025-12-03T07:23:22.497Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069352104Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3632025-12-03T07:23:22.497Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069387588Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"0","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3642025-12-03T07:23:22.497Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069411213Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"1","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3652025-12-03T07:23:22.497Z{"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":"2025-12-03T07:23:22.069477222Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3662025-12-03T07:23:22.497Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2025-12-03T07:23:22.069529433Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3672025-12-03T07:23:22.497Z{"msg":"ds_connection connected from Ok(127.0.0.1:54862)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069561737Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"0","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3682025-12-03T07:23:22.497Z{"msg":"ds_connection connected from Ok(127.0.0.1:41388)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069586913Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"1","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3692025-12-03T07:23:22.497Z{"msg":"downstairs task for 2 stopped due to ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" })","v":0,"name":"crucible","level":40,"time":"2025-12-03T07:23:22.069623726Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3702025-12-03T07:23:22.498Z{"msg":"sleeping for 10s before connecting","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069709221Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3712025-12-03T07:23:22.498Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.069753323Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3722025-12-03T07:23:22.498Z{"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":"2025-12-03T07:23:22.07090483Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"1","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3732025-12-03T07:23:22.498Z{"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":"2025-12-03T07:23:22.070949033Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"0","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3742025-12-03T07:23:22.498Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.071312698Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3752025-12-03T07:23:22.501Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:22.071379307Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3762025-12-03T07:23:32.499Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.071012632Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3772025-12-03T07:23:32.499Z{"msg":"ds_connection connected from Ok(127.0.0.1:55495)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.071102876Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"io task","client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3782025-12-03T07:23:32.504Z{"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":"2025-12-03T07:23:32.072628578Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3792025-12-03T07:23:32.504Z{"msg":"[0]R flush_numbers: [1497, 1497, 1497, 1497, 1497]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073043994Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3802025-12-03T07:23:32.504Z{"msg":"[0]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073078108Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3812025-12-03T07:23:32.504Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073097025Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3822025-12-03T07:23:32.504Z{"msg":"[1]R flush_numbers: [1497, 1497, 1497, 1497, 1497]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073122531Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3832025-12-03T07:23:32.504Z{"msg":"[1]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073140677Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3842025-12-03T07:23:32.504Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073166573Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3852025-12-03T07:23:32.504Z{"msg":"[2]R flush_numbers: [1496, 1496, 1496, 1496, 1496]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073185049Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3862025-12-03T07:23:32.504Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073209415Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3872025-12-03T07:23:32.504Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073227112Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3882025-12-03T07:23:32.504Z{"msg":"Max found gen is 33","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073250938Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3892025-12-03T07:23:32.504Z{"msg":"Generation requested: 33 >= found:33","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073269025Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3902025-12-03T07:23:32.504Z{"msg":"Next flush: 1498","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073285222Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3912025-12-03T07:23:32.504Z{"msg":"extent 0 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073320466Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3922025-12-03T07:23:32.504Z{"msg":"extent:0 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073356059Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3932025-12-03T07:23:32.504Z{"msg":"found dest for source 0 for extent at index 0 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073375726Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3942025-12-03T07:23:32.504Z{"msg":"extent 1 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.07340977Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3952025-12-03T07:23:32.504Z{"msg":"extent:1 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073443954Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3962025-12-03T07:23:32.504Z{"msg":"found dest for source 0 for extent at index 1 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073470409Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3972025-12-03T07:23:32.504Z{"msg":"extent 2 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073497445Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3982025-12-03T07:23:32.504Z{"msg":"extent:2 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073531608Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
3992025-12-03T07:23:32.505Z{"msg":"found dest for source 0 for extent at index 2 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073559974Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4002025-12-03T07:23:32.505Z{"msg":"extent 3 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073587389Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4012025-12-03T07:23:32.505Z{"msg":"extent:3 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073620653Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4022025-12-03T07:23:32.505Z{"msg":"found dest for source 0 for extent at index 3 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073646828Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4032025-12-03T07:23:32.505Z{"msg":"extent 4 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073673663Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4042025-12-03T07:23:32.505Z{"msg":"extent:4 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1497, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1496, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073707397Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4052025-12-03T07:23:32.505Z{"msg":"found dest for source 0 for extent at index 4 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073726114Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"mend","":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4062025-12-03T07:23:32.505Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073771556Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"0","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4072025-12-03T07:23:32.505Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073811969Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"1","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4082025-12-03T07:23:32.505Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073832875Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4092025-12-03T07:23:32.505Z{"msg":"Full repair list: {ExtentId(2): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(4): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(0): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(1): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(3): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }}","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.073872348Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4102025-12-03T07:23:32.505Z{"msg":"Task list: [ReconcileIO { id: ReconciliationId(0), op: ExtentFlush { repair_id: ReconciliationId(0), extent_id: ExtentId(2), client_id: ClientId(0), flush_number: 1498, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(1), op: ExtentClose { repair_id: ReconciliationId(1), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(2), op: ExtentRepair { repair_id: ReconciliationId(2), 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(3), op: ExtentReopen { repair_id: ReconciliationId(3), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(4), op: ExtentFlush { repair_id: ReconciliationId(4), extent_id: ExtentId(4), client_id: ClientId(0), flush_number: 1498, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(5), op: ExtentClose { repair_id: ReconciliationId(5), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(6), op: ExtentRepair { repair_id: ReconciliationId(6), 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(7), op: ExtentReopen { repair_id: ReconciliationId(7), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(8), op: ExtentFlush { repair_id: ReconciliationId(8), extent_id: ExtentId(0), client_id: ClientId(0), flush_number: 1498, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(9), op: ExtentClose { repair_id: ReconciliationId(9), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(10), op: ExtentRepair { repair_id: ReconciliationId(10), 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(11), op: ExtentReopen { repair_id: ReconciliationId(11), extent_id: ExtentId(0) }, 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: 1498, 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(3), client_id: ClientId(0), flush_number: 1498, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(17), op: ExtentClose { repair_id: ReconciliationId(17), extent_id: ExtentId(3) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(18), op: ExtentRepair { repair_id: ReconciliationId(18), 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(19), op: ExtentReopen { repair_id: ReconciliationId(19), extent_id: ExtentId(3) }, state: ClientData([New, New, New]) }]","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.074074933Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4112025-12-03T07:23:32.505Z{"msg":"starting reconciliation 01212079-78a4-497b-8816-baa53f28e9ca: found 20 extents that need repair","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.074106677Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4122025-12-03T07:23:32.505Z{"msg":"sending reconcile request ReconciliationId(2)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.074129543Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4132025-12-03T07:23:32.516Z{"msg":"sending reconcile request ReconciliationId(6)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.0881723Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4142025-12-03T07:23:32.519Z{"msg":"sending reconcile request ReconciliationId(10)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.091968752Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4152025-12-03T07:23:32.523Z{"msg":"sending reconcile request ReconciliationId(14)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.095685237Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4162025-12-03T07:23:32.527Z{"msg":"sending reconcile request ReconciliationId(18)","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.099449664Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4172025-12-03T07:23:32.530Z{"msg":"done with reconciliation","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.102604269Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"":"downstairs","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4182025-12-03T07:23:32.530Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.1026531Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"0","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4192025-12-03T07:23:32.533Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.102684985Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"1","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4202025-12-03T07:23:32.533Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.102722348Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"client":"2","":"downstairs","session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4212025-12-03T07:23:32.533Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.102754792Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4222025-12-03T07:23:32.533Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.102795875Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4232025-12-03T07:23:32.533Z{"msg":"29e49175-9c90-452c-a4bb-58fb54641bfc is now active with session: 782bab24-07f9-4452-973d-b47360ee807f","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.10282402Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253,"session_id":"782bab24-07f9-4452-973d-b47360ee807f"}
4242025-12-03T07:23:32.533Z{"Wait for a query_work_queue command to finish before sending IO
4252025-12-03T07:23:32.533Zmsg":"The guest has finished waiting for activation with:33","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.102867053Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253}
4262025-12-03T07:23:32.533Z{"msg":"Activated sub_volume 29e49175-9c90-452c-a4bb-58fb54641bfc","v":0,"name":"crucible","level":30,"time":"2025-12-03T07:23:32.102903786Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253}
4272025-12-03T07:23:32.533ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
4282025-12-03T07:23:32.533ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
4292025-12-03T07:23:32.533ZRead and Verify all blocks (0..50 range:true)
4302025-12-03T07:23:32.537ZWrote out file "/var/tmp/test_up-build/verify_file"
4312025-12-03T07:23:32.537ZVerify test completed
4322025-12-03T07:23:32.540ZWrote out file "/var/tmp/test_up-build/verify_file"
4332025-12-03T07:23:32.540ZCLIENT: Tests done. All submitted work has been ACK'd
4342025-12-03T07:23:32.540Z----------------------------------------------------------------
4352025-12-03T07:23:32.540Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:1
4362025-12-03T07:23:32.540ZStates: Active Active Active
4372025-12-03T07:23:32.540ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
4382025-12-03T07:23:32.540Z 1000 Acked Read 50 Done Done Done false
4392025-12-03T07:23:32.541Z STATES DS:0 DS:1 DS:2 TOTAL
4402025-12-03T07:23:32.541Z Sent 0 0 0 0
4412025-12-03T07:23:32.541Z Done 1 1 1 3
4422025-12-03T07:23:32.541Z Skipped 0 0 0 0
4432025-12-03T07:23:32.541Z Error 0 0 0 0
4442025-12-03T07:23:32.541ZLast Flush: None None None
4452025-12-03T07:23:32.541ZDownstairs last five completed:
4462025-12-03T07:23:32.541ZUpstairs last five completed: 1000
4472025-12-03T07:23:32.541ZCLIENT: Up:0 ds:1 act:3
4482025-12-03T07:23:36.541Z----------------------------------------------------------------
4492025-12-03T07:23:36.541Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:0
4502025-12-03T07:23:36.541ZDownstairs last five completed: 1001 1000
4512025-12-03T07:23:36.541ZUpstairs last five completed: 1001 1000
4522025-12-03T07:23:36.541ZCLIENT: Up:0 ds:0 act:3
4532025-12-03T07:23:36.541ZCLIENT: All crucible jobs finished, exiting program
4542025-12-03T07:23:36.545Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-12-03T07:23:36.112757735Z","hostname":"w-01KBHHBAC3N5G1974Q74SJ2B4D","pid":1253}
4552025-12-03T07:23:36.548ZRepair part 2 passed
4562025-12-03T07:23:36.551Z/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
4572025-12-03T07:23:36.566ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
4582025-12-03T07:23:36.566Z 0 000-009 32 32 32 1497 1497 1497 F F F
4592025-12-03T07:23:36.566Z 1 010-019 32 32 32 1497 1497 1497 F F F
4602025-12-03T07:23:36.566Z 2 020-029 32 32 32 1497 1497 1497 F F F
4612025-12-03T07:23:36.566Z 3 030-039 32 32 32 1497 1497 1497 F F F
4622025-12-03T07:23:36.566Z 4 040-049 32 32 32 1497 1497 1497 F F F
4632025-12-03T07:23:36.566ZMax gen: 32, Max flush: 1497
4642025-12-03T07:23:36.571Zdump test passed
4652025-12-03T07:23:36.573Z/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
4662025-12-03T07:23:36.587Z Extent 1
4672025-12-03T07:23:36.590ZGEN 32 32 32
4682025-12-03T07:23:36.590ZFLUSH_ID 1497 1497 1497
4692025-12-03T07:23:36.590ZDIRTY
4702025-12-03T07:23:36.590Z
4712025-12-03T07:23:36.590ZBLOCK D0 D1 D2 C0 C1 C2 DIFF
4722025-12-03T07:23:36.590Z010 A A A A A A
4732025-12-03T07:23:36.593Z011 A A A A A A
4742025-12-03T07:23:36.593Z012 A A A A A A
4752025-12-03T07:23:36.593Z013 A A A A A A
4762025-12-03T07:23:36.596Z014 A A A A A A
4772025-12-03T07:23:36.596Z015 A A A A A A
4782025-12-03T07:23:36.599Z016 A A A A A A
4792025-12-03T07:23:36.599Z017 A A A A A A
4802025-12-03T07:23:36.602Z018 A A A A A A
4812025-12-03T07:23:36.602Z019 A A A A A A
4822025-12-03T07:23:36.606Zdump extent test passed
4832025-12-03T07:23:36.609Z/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
4842025-12-03T07:23:36.622ZExtent 2 Block in extent 0 Actual block 20
4852025-12-03T07:23:36.622Z
4862025-12-03T07:23:36.626Z DATA SHA256 VER
4872025-12-03T07:23:36.626Z------ ---------------------------------------------------------------- ---
4882025-12-03T07:23:36.626Z 0 ad3d0e88276af7eb1f904413516e1a8c1f9c2fa8b17b86b2d842d08303e90aa2 A
4892025-12-03T07:23:36.629Z 1 ad3d0e88276af7eb1f904413516e1a8c1f9c2fa8b17b86b2d842d08303e90aa2 A
4902025-12-03T07:23:36.629Z 2 ad3d0e88276af7eb1f904413516e1a8c1f9c2fa8b17b86b2d842d08303e90aa2 A
4912025-12-03T07:23:36.629Z
4922025-12-03T07:23:36.629ZNONCES 0 1 2 DIFF
4932025-12-03T07:23:36.629Z------ ------------------------ ------------------------ ------------------------ -----
4942025-12-03T07:23:36.629Z
4952025-12-03T07:23:36.629Z TAGS 0 1 2 DIFF
4962025-12-03T07:23:36.629Z------ -------------------------------- -------------------------------- -------------------------------- -----
4972025-12-03T07:23:36.629Z
4982025-12-03T07:23:36.629ZHASHES 0 1 2 DIFF
4992025-12-03T07:23:36.629Z------ ---------------- ---------------- ---------------- -----
5002025-12-03T07:23:36.629Z 0 42916ab6fa364c70 42916ab6fa364c70 42916ab6fa364c70
5012025-12-03T07:23:36.629Z
5022025-12-03T07:23:36.632Zdump block test passed
5032025-12-03T07:23:36.632ZInitial upstairs tests have completed, stopping all downstairs
5042025-12-03T07:23:41.696ZCreating 4 larger downstairs regions
5052025-12-03T07:23:41.887ZStarting 4 downstairs
5062025-12-03T07:23:46.895Zdsc restarted at PID: 1266
5072025-12-03T07:23:47.126ZNow do the replace-reconcile test
5082025-12-03T07:23:47.181ZUsing 8840 for the replacement port
5092025-12-03T07:26:58.541ZCompleted test: replace-reconcile
5102025-12-03T07:26:58.544ZNow do the replace-before-active test
5112025-12-03T07:29:54.920ZCompleted test: replace-before-active
5122025-12-03T07:29:54.923ZAll tests have completed, stopping all downstairs
5132025-12-03T07:29:54.980Z
5142025-12-03T07:29:54.980ZAll Tests have passed
5152025-12-03T07:29:54.983Z7:50 Test duration
5162025-12-03T07:29:54.983Z
5172025-12-03T07:29:54.983Zreal 7:49.576760106
5182025-12-03T07:29:54.983Zuser 1:47.852227319
5192025-12-03T07:29:54.983Zsys 14.193510316
5202025-12-03T07:29:54.983Ztrap 0.198852012
5212025-12-03T07:29:54.983Ztflt 0.019371666
5222025-12-03T07:29:54.983Zdflt 0.015324673
5232025-12-03T07:29:54.983Zkflt 0.001269492
5242025-12-03T07:29:54.983Zlock 4:27:22.237616136
5252025-12-03T07:29:54.983Zslp 20:57.508571094
5262025-12-03T07:29:54.983Zlat 17.007771966
5272025-12-03T07:29:54.983Zstop 0.018837702
5282025-12-03T07:29:54.983Z+ echo 'test-up-unencrypted ends'
5292025-12-03T07:29:54.983Ztest-up-unencrypted ends
5302025-12-03T07:29:59.987Zprocess exited: duration 479928 ms, exit code 0
5312025-12-03T07:29:59.987Zexec warning: : stdio descriptors remain open after task exit; waiting 60 seconds for them to close
5322025-12-03T07:31:00.043Zexec warning: : stdout descriptor may be held open by a background process; giving up!
5332025-12-03T07:31:00.043Zexec warning: : stderr descriptor may be held open by a background process; giving up!
 
5342025-12-03T07:31:00.056Zfound 14 output files
5352025-12-03T07:31:00.056Zuploading: /tmp/test_up-build/dsc-out.txt (44655 bytes)
5362025-12-03T07:31:01.070Zuploaded: /tmp/test_up-build/dsc-out.txt
5372025-12-03T07:31:01.070Zuploading: /tmp/test_up-build/test_up_out.txt (21861461 bytes)
5382025-12-03T07:31:02.311Zuploaded: /tmp/test_up-build/test_up_out.txt
5392025-12-03T07:31:02.314Zuploading: /tmp/test_up-build/dsc/downstairs-8810.txt (2509 bytes)
5402025-12-03T07:31:03.321Zuploaded: /tmp/test_up-build/dsc/downstairs-8810.txt
5412025-12-03T07:31:03.321Zuploading: /tmp/test_up-build/dsc/downstairs-8820.txt (548359 bytes)
5422025-12-03T07:31:04.344Zuploaded: /tmp/test_up-build/dsc/downstairs-8820.txt
5432025-12-03T07:31:04.347Zuploading: /tmp/test_up-build/dsc/downstairs-8830.txt (979551 bytes)
5442025-12-03T07:31:05.371Zuploaded: /tmp/test_up-build/dsc/downstairs-8830.txt
5452025-12-03T07:31:05.374Zuploading: /tmp/test_up-build/dsc/downstairs-8840.txt (543079 bytes)
5462025-12-03T07:31:06.394Zuploaded: /tmp/test_up-build/dsc/downstairs-8840.txt
5472025-12-03T07:31:06.397Zuploading: /tmp/debug/df.txt (1270 bytes)
5482025-12-03T07:31:07.406Zuploaded: /tmp/debug/df.txt
5492025-12-03T07:31:07.410Zuploading: /tmp/debug/dtrace.txt (472628 bytes)
5502025-12-03T07:31:07.426Zupload warning: file "/tmp/debug/dtrace.txt" changed size mid upload: 472628 -> 566342
5512025-12-03T07:31:08.434Zuploaded: /tmp/debug/dtrace.txt
5522025-12-03T07:31:08.437Zuploading: /tmp/debug/iostat.txt (161046 bytes)
5532025-12-03T07:31:08.446Zupload warning: file "/tmp/debug/iostat.txt" changed size mid upload: 161046 -> 163755
5542025-12-03T07:31:09.455Zuploaded: /tmp/debug/iostat.txt
5552025-12-03T07:31:09.458Zuploading: /tmp/debug/mpstat.txt (390585 bytes)
5562025-12-03T07:31:09.470Zupload warning: file "/tmp/debug/mpstat.txt" changed size mid upload: 390585 -> 397885
5572025-12-03T07:31:10.479Zuploaded: /tmp/debug/mpstat.txt
5582025-12-03T07:31:10.483Zuploading: /tmp/debug/paging.txt (70592 bytes)
5592025-12-03T07:31:10.489Zupload warning: file "/tmp/debug/paging.txt" changed size mid upload: 70592 -> 72026
5602025-12-03T07:31:11.496Zuploaded: /tmp/debug/paging.txt
5612025-12-03T07:31:11.496Zuploading: /tmp/debug/prstat.txt (752576 bytes)
5622025-12-03T07:31:11.518Zupload warning: file "/tmp/debug/prstat.txt" changed size mid upload: 752576 -> 768119
5632025-12-03T07:31:12.528Zuploaded: /tmp/debug/prstat.txt
5642025-12-03T07:31:12.528Zuploading: /tmp/debug/psrinfo.txt (1528 bytes)
5652025-12-03T07:31:13.538Zuploaded: /tmp/debug/psrinfo.txt
5662025-12-03T07:31:13.538Zuploading: /tmp/debug/upstairs-info.txt (53669 bytes)
5672025-12-03T07:31:14.554Zuploaded: /tmp/debug/upstairs-info.txt