01KN2HMMVDSRB4GRXDXBZBFNS6: 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: 01KN2HN1ES2RQ5C63VG78KYKCS

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-03-31T18:30:23.837Zjob dependencies complete; ready to run (waiting for 16 m 4 s)
22026-03-31T18:33:51.708Zjob assigned to worker 01KN2JQH32YFM50QY6QR5YJKAX [factory aws, i-0f78271a98523b53f] (queued for 3 m 27 s)
32026-03-31T18:33:58.505Zdownloading input: /input/build/work/bins/crucible-downstairs.gz
42026-03-31T18:34:00.168Zdownloaded input: /input/build/work/bins/crucible-downstairs.gz
52026-03-31T18:34:00.172Zdownloading input: /input/build/work/bins/crucible-hammer.gz
62026-03-31T18:34:01.747Zdownloaded input: /input/build/work/bins/crucible-hammer.gz
72026-03-31T18:34:01.751Zdownloading input: /input/build/work/bins/crutest.gz
82026-03-31T18:34:03.262Zdownloaded input: /input/build/work/bins/crutest.gz
92026-03-31T18:34:03.262Zdownloading input: /input/build/work/bins/dsc.gz
102026-03-31T18:34:04.088Zdownloaded input: /input/build/work/bins/dsc.gz
112026-03-31T18:34:04.091Zdownloading input: /input/build/work/scripts/perf-downstairs-tick.d
122026-03-31T18:34:04.118Zdownloaded input: /input/build/work/scripts/perf-downstairs-tick.d
132026-03-31T18:34:04.121Zdownloading input: /input/build/work/scripts/test_ds.sh
142026-03-31T18:34:04.142Zdownloaded input: /input/build/work/scripts/test_ds.sh
152026-03-31T18:34:04.145Zdownloading input: /input/build/work/scripts/test_live_repair.sh
162026-03-31T18:34:04.170Zdownloaded input: /input/build/work/scripts/test_live_repair.sh
172026-03-31T18:34:04.173Zdownloading input: /input/build/work/scripts/test_repair.sh
182026-03-31T18:34:04.194Zdownloaded input: /input/build/work/scripts/test_repair.sh
192026-03-31T18:34:04.194Zdownloading input: /input/build/work/scripts/test_replay.sh
202026-03-31T18:34:04.220Zdownloaded input: /input/build/work/scripts/test_replay.sh
212026-03-31T18:34:04.220Zdownloading input: /input/build/work/scripts/test_up.sh
222026-03-31T18:34:04.247Zdownloaded input: /input/build/work/scripts/test_up.sh
232026-03-31T18:34:04.247Zdownloading input: /input/build/work/scripts/upstairs_info.d
242026-03-31T18:34:04.271Zdownloaded input: /input/build/work/scripts/upstairs_info.d
252026-03-31T18:34:04.274Zdownloading input: /input/build/tmp/cargo-test-out.log
262026-03-31T18:34:04.814Zdownloaded input: /input/build/tmp/cargo-test-out.log
 
272026-03-31T18:34:04.815Zstarting task 0: "setup"
282026-03-31T18:34:04.819Z++ uname -s
292026-03-31T18:34:04.822Z+ kern=SunOS
302026-03-31T18:34:04.822Z+ build_user=build
312026-03-31T18:34:04.822Z+ build_uid=12345
322026-03-31T18:34:04.822Z+ work_dir=/work
332026-03-31T18:34:04.822Z+ input_dir=/input
342026-03-31T18:34:04.822Z+ [[ 0 == 12345 ]]
352026-03-31T18:34:04.822Z+ case "$kern" in
362026-03-31T18:34:04.822Z+ groupadd -g 12345 build
372026-03-31T18:34:04.825Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
382026-03-31T18:34:06.830Z+ zfs create -o mountpoint=/work rpool/work
392026-03-31T18:34:07.097Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
402026-03-31T18:34:07.100Z+ home_fs=zfs
412026-03-31T18:34:07.100Z+ [[ zfs == autofs ]]
422026-03-31T18:34:07.100Z+ mkdir -p /home/build
432026-03-31T18:34:07.100Z+ chown build:build /home/build /work
442026-03-31T18:34:09.101Z+ chmod 0700 /home/build /work
452026-03-31T18:34:09.105Zprocess exited: duration 4289 ms, exit code 0
 
462026-03-31T18:34:09.111Zstarting task 1: "authentication"
472026-03-31T18:34:09.128Zprocess exited: duration 17 ms, exit code 0
 
482026-03-31T18:34:09.135Zstarting task 2: "build"
492026-03-31T18:34:09.138Z+ banner cores
502026-03-31T18:34:09.141Z
512026-03-31T18:34:09.141Z #### #### ##### ###### ####
522026-03-31T18:34:09.141Z # # # # # # # #
532026-03-31T18:34:09.141Z # # # # # ##### ####
542026-03-31T18:34:09.141Z # # # ##### # #
552026-03-31T18:34:09.141Z # # # # # # # # #
562026-03-31T18:34:09.141Z #### #### # # ###### ####
572026-03-31T18:34:09.141Z
582026-03-31T18:34:09.141Z+ pfexec coreadm -i /tmp/core.%f.%p -g /tmp/core.%f.%p -e global -e log -e proc-setid -e global-setid
592026-03-31T18:34:09.146Z+ echo 'input bins dir contains:'
602026-03-31T18:34:09.149Zinput bins dir contains:
612026-03-31T18:34:09.149Z+ ls -ltr /input/build/work/bins
622026-03-31T18:34:09.149Ztotal 1008936
632026-03-31T18:34:09.149Z-rw-r--r-- 1 root root 154673920 Mar 31 18:33 crucible-downstairs.gz
642026-03-31T18:34:09.149Z-rw-r--r-- 1 root root 142002690 Mar 31 18:34 crucible-hammer.gz
652026-03-31T18:34:09.149Z-rw-r--r-- 1 root root 147731665 Mar 31 18:34 crutest.gz
662026-03-31T18:34:09.149Z-rw-r--r-- 1 root root 71825661 Mar 31 18:34 dsc.gz
672026-03-31T18:34:09.149Z+ banner unpack
682026-03-31T18:34:09.149Z
692026-03-31T18:34:09.149Z # # # # ##### ## #### # #
702026-03-31T18:34:09.149Z # # ## # # # # # # # # #
712026-03-31T18:34:09.149Z # # # # # # # # # # ####
722026-03-31T18:34:09.149Z # # # # # ##### ###### # # #
732026-03-31T18:34:09.149Z # # # ## # # # # # # #
742026-03-31T18:34:09.149Z #### # # # # # #### # #
752026-03-31T18:34:09.149Z
762026-03-31T18:34:09.149Z+ mkdir -p /var/tmp/bins
772026-03-31T18:34:09.153Z+ for t in "$input/bins/"*.gz
782026-03-31T18:34:09.153Z++ basename /input/build/work/bins/crucible-downstairs.gz
792026-03-31T18:34:09.153Z+ b=crucible-downstairs.gz
802026-03-31T18:34:09.153Z+ b=crucible-downstairs
812026-03-31T18:34:09.153Z+ gunzip
822026-03-31T18:34:11.758Z+ chmod +x /var/tmp/bins/crucible-downstairs
832026-03-31T18:34:11.761Z+ for t in "$input/bins/"*.gz
842026-03-31T18:34:11.761Z++ basename /input/build/work/bins/crucible-hammer.gz
852026-03-31T18:34:11.761Z+ b=crucible-hammer.gz
862026-03-31T18:34:11.761Z+ b=crucible-hammer
872026-03-31T18:34:11.761Z+ gunzip
882026-03-31T18:34:14.097Z+ chmod +x /var/tmp/bins/crucible-hammer
892026-03-31T18:34:14.100Z+ for t in "$input/bins/"*.gz
902026-03-31T18:34:14.100Z++ basename /input/build/work/bins/crutest.gz
912026-03-31T18:34:14.103Z+ b=crutest.gz
922026-03-31T18:34:14.103Z+ b=crutest
932026-03-31T18:34:14.103Z+ gunzip
942026-03-31T18:34:16.569Z+ chmod +x /var/tmp/bins/crutest
952026-03-31T18:34:16.572Z+ for t in "$input/bins/"*.gz
962026-03-31T18:34:16.572Z++ basename /input/build/work/bins/dsc.gz
972026-03-31T18:34:16.572Z+ b=dsc.gz
982026-03-31T18:34:16.572Z+ b=dsc
992026-03-31T18:34:16.572Z+ gunzip
1002026-03-31T18:34:17.754Z+ chmod +x /var/tmp/bins/dsc
1012026-03-31T18:34:17.757Z+ export BINDIR=/var/tmp/bins
1022026-03-31T18:34:17.757Z+ BINDIR=/var/tmp/bins
1032026-03-31T18:34:17.757Z+ export RUST_BACKTRACE=1
1042026-03-31T18:34:17.757Z+ RUST_BACKTRACE=1
1052026-03-31T18:34:17.757Z+ jobpid=1088
1062026-03-31T18:34:17.758Z+ echo 'Setup debug logging'
1072026-03-31T18:34:17.758Z+ mkdir /tmp/debug
1082026-03-31T18:34:17.758ZSetup debug logging
1092026-03-31T18:34:17.758Z+ sleep 3600
1102026-03-31T18:34:17.761Z+ psrinfo -v
1112026-03-31T18:34:17.761Z+ df -h
1122026-03-31T18:34:17.765Z+ prstat -d d -mLc 1
1132026-03-31T18:34:17.769Z+ iostat -T d -xn 1
1142026-03-31T18:34:17.769Z+ mpstat -T d 1
1152026-03-31T18:34:17.769Z+ vmstat -T d -p 1
1162026-03-31T18:34:17.769Z+ pfexec dtrace -Z -s /input/build/work/scripts/perf-downstairs-tick.d
1172026-03-31T18:34:17.769Z+ banner test_up_encrypted
1182026-03-31T18:34:17.769Z+ pfexec dtrace -Z -s /input/build/work/scripts/upstairs_info.d
1192026-03-31T18:34:17.773Z
1202026-03-31T18:34:17.773Z ##### ###### #### ##### # # ##### ###### # #
1212026-03-31T18:34:17.773Z # # # # # # # # # ## #
1222026-03-31T18:34:17.773Z # ##### #### # # # # # ##### # # #
1232026-03-31T18:34:17.773Z # # # # # # ##### # # # #
1242026-03-31T18:34:17.773Z # # # # # # # # # # ##
1252026-03-31T18:34:17.773Z # ###### #### # ####### #### # ####### ###### # #
1262026-03-31T18:34:17.773Z
1272026-03-31T18:34:17.773Z+ ptime -m bash /input/build/work/scripts/test_up.sh -N encrypted
1282026-03-31T18:34:17.777Z/input/build/work
1292026-03-31T18:34:17.786ZTurn off color for downstairs dump
1302026-03-31T18:34:17.798ZUpstairs using key: CMWzhrt6tJYolFXRBqKirXJn1gzs9r1U7OVws39zSt4=
1312026-03-31T18:34:17.801Zdsc output goes to /tmp/test_up-build/dsc-out.txt
1322026-03-31T18:34:17.801ZCreating 3 downstairs regions
1332026-03-31T18:34:18.011ZStarting 3 downstairs
1342026-03-31T18:34:18.014Zdsc started at PID: 1134
1352026-03-31T18:34:23.062ZDisable automatic restart on all downstairs
1362026-03-31T18:34:23.074Z
1372026-03-31T18:34:23.074ZBegin tests, output goes to /tmp/test_up-build/test_up_out.txt
1382026-03-31T18:34:23.077ZRunning test: span
1392026-03-31T18:34:27.166ZCompleted test: span
1402026-03-31T18:34:32.173ZRunning test: big
1412026-03-31T18:34:36.335ZCompleted test: big
1422026-03-31T18:34:41.342ZRunning test: dep
1432026-03-31T18:35:12.685ZCompleted test: dep
1442026-03-31T18:35:17.691ZRunning test: balloon
1452026-03-31T18:35:42.821ZCompleted test: balloon
1462026-03-31T18:35:47.827ZRunning test: deactivate
1472026-03-31T18:35:52.155ZCompleted test: deactivate
1482026-03-31T18:35:57.162ZRunning hammer
1492026-03-31T18:36:04.644ZRun repair tests
1502026-03-31T18:36:04.647Z/var/tmp/bins/crutest fill -g 31 -q --key CMWzhrt6tJYolFXRBqKirXJn1gzs9r1U7OVws39zSt4= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file
1512026-03-31T18:36:04.664Z{"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-31T18:36:03.219358513Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"task":"crutest"}
1522026-03-31T18:36:04.668Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.219637669Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"task":"crutest"}
1532026-03-31T18:36:04.668Z{"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-31T18:36:03.220391782Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"task":"crutest"}
1542026-03-31T18:36:04.668Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.22063342Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171}
1552026-03-31T18:36:04.668Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"15d1a4bfe3549686eb976ff56710f1466c0e0e4a\",\n git_commit_timestamp: \"2026-03-31T18:13:40.000000000Z\",\n git_branch: \"main\",\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-31T18:36:03.220665899Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171}
1562026-03-31T18:36:04.668Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.220679528Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171}
1572026-03-31T18:36:04.668Z{"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-31T18:36:03.220691677Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171}
1582026-03-31T18:36:04.669Z{"msg":"Crucible 3b9b78cf-2fde-4035-b955-cf8e9392f782 has session id: d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221074879Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1592026-03-31T18:36:04.669Z{"msg":"Upstairs opts: Upstairs UUID: 3b9b78cf-2fde-4035-b955-cf8e9392f782, 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-31T18:36:03.221099037Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1602026-03-31T18:36:04.669Z{"msg":"Crucible stats registered with UUID: 3b9b78cf-2fde-4035-b955-cf8e9392f782","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221113627Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1612026-03-31T18:36:04.669Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2026-03-31T18:36:03.221123186Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1622026-03-31T18:36:04.669Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.22124578Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"io task","client":"0","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1632026-03-31T18:36:04.669Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221266389Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"io task","client":"1","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1642026-03-31T18:36:04.669Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221276719Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"io task","client":"2","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1652026-03-31T18:36:04.669Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.22145958Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"task":"crutest"}
1662026-03-31T18:36:04.669Z{"msg":"The guest has requested activation with gen:31","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221476939Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171}
1672026-03-31T18:36:04.669Z{"msg":"3b9b78cf-2fde-4035-b955-cf8e9392f782 active request set","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221489358Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1682026-03-31T18:36:04.669Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221499138Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"client":"0","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1692026-03-31T18:36:04.669Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221513697Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"client":"1","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1702026-03-31T18:36:04.669Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221523686Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"client":"2","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1712026-03-31T18:36:04.669Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221534056Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"io task","client":"0","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1722026-03-31T18:36:04.669Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221544585Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"io task","client":"2","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1732026-03-31T18:36:04.669Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221555515Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"io task","client":"1","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1742026-03-31T18:36:04.669Z{"msg":"ds_connection connected from Ok(127.0.0.1:35318)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.22164489Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"io task","client":"0","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1752026-03-31T18:36:04.669Z{"msg":"ds_connection connected from Ok(127.0.0.1:61477)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221716007Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"io task","client":"2","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1762026-03-31T18:36:04.669Z{"msg":"ds_connection connected from Ok(127.0.0.1:58455)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.221741146Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"io task","client":"1","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1772026-03-31T18:36:04.669Z{"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-31T18:36:03.222286089Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"client":"2","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1782026-03-31T18:36:04.669Z{"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-31T18:36:03.222301458Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"client":"1","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1792026-03-31T18:36:04.669Z{"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-31T18:36:03.222343726Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"client":"0","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1802026-03-31T18:36:04.669Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.22247435Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1812026-03-31T18:36:04.669Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222486989Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1822026-03-31T18:36:04.669Z{"msg":"[0]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222513768Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1832026-03-31T18:36:04.669Z{"msg":"[0]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222525057Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1842026-03-31T18:36:04.669Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222535717Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1852026-03-31T18:36:04.669Z{"msg":"[1]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222556426Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1862026-03-31T18:36:04.669Z{"msg":"[1]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222566775Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1872026-03-31T18:36:04.669Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222577434Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1882026-03-31T18:36:04.669Z{"msg":"[2]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222587944Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1892026-03-31T18:36:04.669Z{"msg":"[2]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222598413Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1902026-03-31T18:36:04.669Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222608893Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1912026-03-31T18:36:04.669Z{"msg":"Max found gen is 26","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222619262Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1922026-03-31T18:36:04.669ZWait for a query_work_queue command to finish before sending IO
1932026-03-31T18:36:04.670Z{"msg":"Generation requested: 31 >= found:26","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222633862Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1942026-03-31T18:36:04.670Z{"msg":"Next flush: 1502","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222643621Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1952026-03-31T18:36:04.670Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222654041Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"":"downstairs","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1962026-03-31T18:36:04.670Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.22266455Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1972026-03-31T18:36:04.670Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.22267424Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"client":"0","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1982026-03-31T18:36:04.670Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222684229Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"client":"1","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
1992026-03-31T18:36:04.670Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222694449Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"client":"2","":"downstairs","session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
2002026-03-31T18:36:04.670Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222704868Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
2012026-03-31T18:36:04.670Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222715158Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
2022026-03-31T18:36:04.670Z{"msg":"3b9b78cf-2fde-4035-b955-cf8e9392f782 is now active with session: d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222726237Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
2032026-03-31T18:36:04.670Z{"Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2042026-03-31T18:36:04.670Zmsg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222738097Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171,"session_id":"d08dc29d-ceb6-4a3a-ad3d-2691fe4e8434"}
2052026-03-31T18:36:04.670Z{"msg":"The guest has finished waiting for activation with:31","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222748196Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171}
2062026-03-31T18:36:04.670ZFill test
2072026-03-31T18:36:04.670Z{"msg":"Activated sub_volume 3b9b78cf-2fde-4035-b955-cf8e9392f782","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:03.222758146Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171}
2082026-03-31T18:36:04.692ZRead and Verify all blocks (0..50 range:false)
2092026-03-31T18:36:04.715ZWrote out file "/var/tmp/test_up-build/verify_file"
2102026-03-31T18:36:04.715ZCLIENT: Tests done. All submitted work has been ACK'd
2112026-03-31T18:36:04.719Z----------------------------------------------------------------
2122026-03-31T18:36:04.719Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:1
2132026-03-31T18:36:04.719ZStates: Active Active Active
2142026-03-31T18:36:04.719ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2152026-03-31T18:36:04.719Z 1002 Acked Read 50 Done Done Done false
2162026-03-31T18:36:04.720Z STATES DS:0 DS:1 DS:2 TOTAL
2172026-03-31T18:36:04.720Z Sent 0 0 0 0
2182026-03-31T18:36:04.720Z Done 1 1 1 3
2192026-03-31T18:36:04.720Z Skipped 0 0 0 0
2202026-03-31T18:36:04.720Z Error 0 0 0 0
2212026-03-31T18:36:04.720ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
2222026-03-31T18:36:04.720ZDownstairs last five completed: 1001 1000
2232026-03-31T18:36:04.720ZUpstairs last five completed: 1002 1001 1000
2242026-03-31T18:36:04.720ZCLIENT: Up:0 ds:1 act:3
2252026-03-31T18:36:08.716Z----------------------------------------------------------------
2262026-03-31T18:36:08.716Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:0
2272026-03-31T18:36:08.716ZDownstairs last five completed: 1003 1002 1001 1000
2282026-03-31T18:36:08.716ZUpstairs last five completed: 1003 1002 1001 1000
2292026-03-31T18:36:08.716ZCLIENT: Up:0 ds:0 act:3
2302026-03-31T18:36:08.717ZCLIENT: All crucible jobs finished, exiting program
2312026-03-31T18:36:08.719Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2026-03-31T18:36:07.272369888Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1171}
2322026-03-31T18:36:08.724ZRepair setup passed
2332026-03-31T18:36:08.727ZCopy the region for /var/tmp/test_up-build/8830
2342026-03-31T18:36:08.727Zcp -r /var/tmp/test_up-build/8830 /var/tmp/test_up-build/previous
2352026-03-31T18:36:08.730Z/var/tmp/bins/crutest fill -g 32 -q --key CMWzhrt6tJYolFXRBqKirXJn1gzs9r1U7OVws39zSt4= --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-31T18:36:08.748Z{"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-31T18:36:07.303254676Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"task":"crutest"}
2372026-03-31T18:36:08.752Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.30357754Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"task":"crutest"}
2382026-03-31T18:36:08.752Z{"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-31T18:36:07.30439613Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"task":"crutest"}
2392026-03-31T18:36:08.752Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.304634108Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177}
2402026-03-31T18:36:08.752Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"15d1a4bfe3549686eb976ff56710f1466c0e0e4a\",\n git_commit_timestamp: \"2026-03-31T18:13:40.000000000Z\",\n git_branch: \"main\",\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-31T18:36:07.304674126Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177}
2412026-03-31T18:36:08.752Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.304708794Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177}
2422026-03-31T18:36:08.752Z{"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-31T18:36:07.304734083Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177}
2432026-03-31T18:36:08.752Z{"msg":"Crucible 268133d1-22e4-4030-8de1-4ed834a4e45a has session id: 4994d66a-e22f-4eea-8d2b-1153b1d5e6c1","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305051697Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2442026-03-31T18:36:08.752Z{"msg":"Upstairs opts: Upstairs UUID: 268133d1-22e4-4030-8de1-4ed834a4e45a, 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-31T18:36:07.305086766Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2452026-03-31T18:36:08.752Z{"msg":"Crucible stats registered with UUID: 268133d1-22e4-4030-8de1-4ed834a4e45a","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305102305Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2462026-03-31T18:36:08.752Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2026-03-31T18:36:07.305112944Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2472026-03-31T18:36:08.752Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305259027Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"io task","client":"1","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2482026-03-31T18:36:08.752Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305290216Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"io task","client":"2","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2492026-03-31T18:36:08.752Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305301035Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"io task","client":"0","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2502026-03-31T18:36:08.752Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305469207Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"task":"crutest"}
2512026-03-31T18:36:08.752Z{"msg":"The guest has requested activation with gen:32","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305486626Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177}
2522026-03-31T18:36:08.752Z{"msg":"268133d1-22e4-4030-8de1-4ed834a4e45a active request set","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305494766Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2532026-03-31T18:36:08.752Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305507915Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"client":"0","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2542026-03-31T18:36:08.752Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305518544Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"client":"1","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2552026-03-31T18:36:08.752Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305533004Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"client":"2","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2562026-03-31T18:36:08.752Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305543443Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"io task","client":"0","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2572026-03-31T18:36:08.753Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305553853Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"io task","client":"2","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2582026-03-31T18:36:08.753Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305564322Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"io task","client":"1","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2592026-03-31T18:36:08.753Z{"msg":"ds_connection connected from Ok(127.0.0.1:48322)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.30560595Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"io task","client":"2","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2602026-03-31T18:36:08.753Z{"msg":"ds_connection connected from Ok(127.0.0.1:46372)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305632219Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"io task","client":"0","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2612026-03-31T18:36:08.753Z{"msg":"ds_connection connected from Ok(127.0.0.1:34249)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.305703385Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"io task","client":"1","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2622026-03-31T18:36:08.753Z{"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-31T18:36:07.306294616Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"client":"2","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2632026-03-31T18:36:08.753Z{"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-31T18:36:07.306314775Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"client":"1","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2642026-03-31T18:36:08.753Z{"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-31T18:36:07.306327395Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"client":"0","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2652026-03-31T18:36:08.753Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306511296Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2662026-03-31T18:36:08.753Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306528005Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2672026-03-31T18:36:08.753Z{"msg":"[0]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306538444Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2682026-03-31T18:36:08.753Z{"msg":"[0]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306555793Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2692026-03-31T18:36:08.753Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306567403Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2702026-03-31T18:36:08.753Z{"msg":"[1]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306583492Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2712026-03-31T18:36:08.753Z{"msg":"[1]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306594981Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2722026-03-31T18:36:08.753Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306611461Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2732026-03-31T18:36:08.753Z{"msg":"[2]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.30662324Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2742026-03-31T18:36:08.753Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306635059Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2752026-03-31T18:36:08.753Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306646359Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2762026-03-31T18:36:08.753Z{"msg":"Max found gen is 32","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306662278Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2772026-03-31T18:36:08.753Z{"msg":"Generation requested: 32 >= found:32","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306674097Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2782026-03-31T18:36:08.753Z{"msg":"Next flush: 1503","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306685447Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2792026-03-31T18:36:08.757Z{"msg":"All extents match","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO
2802026-03-31T18:36:08.757Z,"time":"2026-03-31T18:36:07.306696316Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"":"downstairs","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2812026-03-31T18:36:08.757Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306716445Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2822026-03-31T18:36:08.757Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306726885Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"client":"0","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2832026-03-31T18:36:08.757Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306746794Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"client":"1","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2842026-03-31T18:36:08.757Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306757643Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"client":"2","":"downstairs","session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2852026-03-31T18:36:08.757Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306773583Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2862026-03-31T18:36:08.757Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306784272Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2872026-03-31T18:36:08.757Z{"msg":"268133d1-22e4-4030-8de1-4ed834a4e45a is now active with session: 4994d66a-e22f-4eea-8d2b-1153b1d5e6c1","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306796601Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2882026-03-31T18:36:08.757Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306811151Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177,"session_id":"4994d66a-e22f-4eea-8d2b-1153b1d5e6c1"}
2892026-03-31T18:36:08.757Z{"msg":"The guest has finished waiting for activation with:32","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.30682221Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177}
2902026-03-31T18:36:08.757Z{"msg":"Activated sub_volume 268133d1-22e4-4030-8de1-4ed834a4e45a","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:07.306840179Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177}
2912026-03-31T18:36:08.757ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2922026-03-31T18:36:08.757ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
2932026-03-31T18:36:08.757ZFill test
2942026-03-31T18:36:08.775ZRead and Verify all blocks (0..50 range:false)
2952026-03-31T18:36:08.799ZWrote out file "/var/tmp/test_up-build/verify_file"
2962026-03-31T18:36:08.799ZCLIENT: Tests done. All submitted work has been ACK'd
2972026-03-31T18:36:08.799Z----------------------------------------------------------------
2982026-03-31T18:36:08.799Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:1
2992026-03-31T18:36:08.799ZStates: Active Active Active
3002026-03-31T18:36:08.803ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
3012026-03-31T18:36:08.803Z 1002 Acked Read 50 Done Done Done false
3022026-03-31T18:36:08.803Z STATES DS:0 DS:1 DS:2 TOTAL
3032026-03-31T18:36:08.803Z Sent 0 0 0 0
3042026-03-31T18:36:08.803Z Done 1 1 1 3
3052026-03-31T18:36:08.803Z Skipped 0 0 0 0
3062026-03-31T18:36:08.803Z Error 0 0 0 0
3072026-03-31T18:36:08.804ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
3082026-03-31T18:36:08.804ZDownstairs last five completed: 1001 1000
3092026-03-31T18:36:08.804ZUpstairs last five completed: 1002 1001 1000
3102026-03-31T18:36:08.804ZCLIENT: Up:0 ds:1 act:3
3112026-03-31T18:36:12.800Z----------------------------------------------------------------
3122026-03-31T18:36:12.800Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:0
3132026-03-31T18:36:12.800ZDownstairs last five completed: 1003 1002 1001 1000
3142026-03-31T18:36:12.801ZUpstairs last five completed: 1003 1002 1001 1000
3152026-03-31T18:36:12.801ZCLIENT: Up:0 ds:0 act:3
3162026-03-31T18:36:12.801ZCLIENT: All crucible jobs finished, exiting program
3172026-03-31T18:36:12.804Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2026-03-31T18:36:11.356149636Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1177}
3182026-03-31T18:36:12.807ZRepair part 1 passed
3192026-03-31T18:36:12.807Z
3202026-03-31T18:36:12.807ZKill the current downstairs
3212026-03-31T18:36:12.848ZDownstairs 2 stopped
3222026-03-31T18:36:12.848Zmv /var/tmp/test_up-build/8830 /var/tmp/test_up-build/new
3232026-03-31T18:36:12.851ZNow put back the original so we have a mismatch
3242026-03-31T18:36:12.851Zmv /var/tmp/test_up-build/previous /var/tmp/test_up-build/8830
3252026-03-31T18:36:12.851ZRestart downstairs with old directory
3262026-03-31T18:36:12.865Z/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-31T18:36:12.876ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
3282026-03-31T18:36:12.879Z 0 000-009 32 32 31 1503 1503 1502 F F F <---
3292026-03-31T18:36:12.879Z 1 010-019 32 32 31 1503 1503 1502 F F F <---
3302026-03-31T18:36:12.879Z 2 020-029 32 32 31 1503 1503 1502 F F F <---
3312026-03-31T18:36:12.879Z 3 030-039 32 32 31 1503 1503 1502 F F F <---
3322026-03-31T18:36:12.881Z 4 040-049 32 32 31 1503 1503 1502 F F F <---
3332026-03-31T18:36:12.881ZMax gen: 32, Max flush: 1503
3342026-03-31T18:36:13.098ZError: Difference in extent metadata found!
3352026-03-31T18:36:13.098Z
3362026-03-31T18:36:13.098ZStack backtrace:
3372026-03-31T18:36:13.098Z 0: anyhow::error::<impl anyhow::Error>::msg
3382026-03-31T18:36:13.099Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.102/src/backtrace.rs:10:14
3392026-03-31T18:36:13.099Z 1: anyhow::__private::format_err
3402026-03-31T18:36:13.099Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.102/src/lib.rs:687:13
3412026-03-31T18:36:13.117Zdump test found error as expected
3422026-03-31T18:36:13.117Z
3432026-03-31T18:36:13.117Z
3442026-03-31T18:36:13.121Z/var/tmp/bins/crutest verify --range -g 33 -q --key CMWzhrt6tJYolFXRBqKirXJn1gzs9r1U7OVws39zSt4= --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-31T18:36:13.135Z{"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-31T18:36:11.690410188Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"task":"crutest"}
3462026-03-31T18:36:13.139Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.690868486Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"task":"crutest"}
3472026-03-31T18:36:13.139Z{"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-31T18:36:11.692073717Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"task":"crutest"}
3482026-03-31T18:36:13.139Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.692313775Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185}
3492026-03-31T18:36:13.139Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"15d1a4bfe3549686eb976ff56710f1466c0e0e4a\",\n git_commit_timestamp: \"2026-03-31T18:13:40.000000000Z\",\n git_branch: \"main\",\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-31T18:36:11.692340793Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185}
3502026-03-31T18:36:13.139Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.692354113Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185}
3512026-03-31T18:36:13.139Z{"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-31T18:36:11.692366932Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185}
3522026-03-31T18:36:13.139Z{"msg":"Crucible b02a6ba2-8f02-4e1c-aa53-6cd0ea8b11a6 has session id: 9dbd2352-077c-4a5a-9a05-c765e9ae2378","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.692844169Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3532026-03-31T18:36:13.139Z{"msg":"Upstairs opts: Upstairs UUID: b02a6ba2-8f02-4e1c-aa53-6cd0ea8b11a6, 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-31T18:36:11.692867167Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3542026-03-31T18:36:13.139Z{"msg":"Crucible stats registered with UUID: b02a6ba2-8f02-4e1c-aa53-6cd0ea8b11a6","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.692881747Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3552026-03-31T18:36:13.139Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2026-03-31T18:36:11.692891296Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3562026-03-31T18:36:13.139Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693101966Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"1","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3572026-03-31T18:36:13.139Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693137444Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"0","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3582026-03-31T18:36:13.139Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693148764Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3592026-03-31T18:36:13.139Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693446359Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"task":"crutest"}
3602026-03-31T18:36:13.139Z{"msg":"The guest has requested activation with gen:33","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693470698Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185}
3612026-03-31T18:36:13.139Z{"msg":"b02a6ba2-8f02-4e1c-aa53-6cd0ea8b11a6 active request set","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693483517Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3622026-03-31T18:36:13.139Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693492857Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"0","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3632026-03-31T18:36:13.139Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693503266Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"1","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3642026-03-31T18:36:13.139Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693513066Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3652026-03-31T18:36:13.139Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693522845Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"0","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3662026-03-31T18:36:13.139Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693533655Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"1","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3672026-03-31T18:36:13.139Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693543714Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3682026-03-31T18:36:13.139Z{"msg":"ds_connection connected from Ok(127.0.0.1:47628)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693576252Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"1","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3692026-03-31T18:36:13.139Z{"msg":"ds_connection connected from Ok(127.0.0.1:52842)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693591112Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"0","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3702026-03-31T18:36:13.139Z{"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-31T18:36:11.693689817Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3712026-03-31T18:36:13.139Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2026-03-31T18:36:11.693706836Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3722026-03-31T18:36:13.139Z{"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-31T18:36:11.693719425Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3732026-03-31T18:36:13.139Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693770883Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3742026-03-31T18:36:13.139Z{"msg":"sleeping for 10s before connecting","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.693788122Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3752026-03-31T18:36:13.143Z{"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-31T18:36:11.694298367Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"1","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3762026-03-31T18:36:13.143Z{"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-31T18:36:11.694329965Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"0","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3772026-03-31T18:36:13.143Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.694455499Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3782026-03-31T18:36:13.143Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:11.694467829Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3792026-03-31T18:36:23.140Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.694416071Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3802026-03-31T18:36:23.140Z{"msg":"ds_connection connected from Ok(127.0.0.1:60678)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.694501117Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"io task","client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3812026-03-31T18:36:23.146Z{"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-31T18:36:21.695952855Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3822026-03-31T18:36:23.146Z{"msg":"[0]R flush_numbers: [1503, 1503, 1503, 1503, 1503]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696244351Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3832026-03-31T18:36:23.146Z{"msg":"[0]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.69627061Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3842026-03-31T18:36:23.146Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696288689Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3852026-03-31T18:36:23.146Z{"msg":"[1]R flush_numbers: [1503, 1503, 1503, 1503, 1503]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696313388Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3862026-03-31T18:36:23.146Z{"msg":"[1]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696329527Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3872026-03-31T18:36:23.146Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696353796Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3882026-03-31T18:36:23.146Z{"msg":"[2]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696370625Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3892026-03-31T18:36:23.146Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696387144Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3902026-03-31T18:36:23.146Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696410863Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3912026-03-31T18:36:23.146Z{"msg":"Max found gen is 33","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696426572Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3922026-03-31T18:36:23.146Z{"msg":"Generation requested: 33 >= found:33","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696450051Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3932026-03-31T18:36:23.146Z{"msg":"Next flush: 1504","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.69646623Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3942026-03-31T18:36:23.146Z{"msg":"extent 0 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696497839Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3952026-03-31T18:36:23.146Z{"msg":"extent:0 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696529237Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3962026-03-31T18:36:23.146Z{"msg":"found dest for source 0 for extent at index 0 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696548286Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3972026-03-31T18:36:23.146Z{"msg":"extent 1 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696572065Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3982026-03-31T18:36:23.146Z{"msg":"extent:1 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696595874Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
3992026-03-31T18:36:23.146Z{"msg":"found dest for source 0 for extent at index 1 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696620892Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4002026-03-31T18:36:23.146Z{"msg":"extent 2 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696644261Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4012026-03-31T18:36:23.146Z{"msg":"extent:2 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.69667278Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4022026-03-31T18:36:23.146Z{"msg":"found dest for source 0 for extent at index 2 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696695189Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4032026-03-31T18:36:23.146Z{"msg":"extent 3 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696717978Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4042026-03-31T18:36:23.146Z{"msg":"extent:3 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696747326Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4052026-03-31T18:36:23.146Z{"msg":"found dest for source 0 for extent at index 3 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696770235Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4062026-03-31T18:36:23.146Z{"msg":"extent 4 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696798354Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4072026-03-31T18:36:23.146Z{"msg":"extent:4 ClientMap(ClientData([Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 32, flush: 1503, dirty: false }), Some(ExtentMetadata { generation: 31, flush: 1502, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696820703Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4082026-03-31T18:36:23.146Z{"msg":"found dest for source 0 for extent at index 4 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696837562Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"mend","":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4092026-03-31T18:36:23.146Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696861371Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"0","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4102026-03-31T18:36:23.146Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.69687799Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"1","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4112026-03-31T18:36:23.146Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.696895019Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4122026-03-31T18:36:23.147Z{"msg":"Full repair list: {ExtentId(2): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(4): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(3): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(1): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(0): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }}","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.697004814Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4132026-03-31T18:36:23.147Z{"msg":"Task list: [ReconcileIO { id: ReconciliationId(0), op: ExtentFlush { repair_id: ReconciliationId(0), extent_id: ExtentId(2), client_id: ClientId(0), flush_number: 1504, 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: 1504, 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(3), client_id: ClientId(0), flush_number: 1504, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(9), op: ExtentClose { repair_id: ReconciliationId(9), extent_id: ExtentId(3) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(10), op: ExtentRepair { repair_id: ReconciliationId(10), 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(11), op: ExtentReopen { repair_id: ReconciliationId(11), extent_id: ExtentId(3) }, 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: 1504, 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(0), client_id: ClientId(0), flush_number: 1504, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(17), op: ExtentClose { repair_id: ReconciliationId(17), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(18), op: ExtentRepair { repair_id: ReconciliationId(18), 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(19), op: ExtentReopen { repair_id: ReconciliationId(19), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }]","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.697192904Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4142026-03-31T18:36:23.147Z{"msg":"starting reconciliation 5d9b6278-506f-48ba-9046-de11a2a2953f: found 20 extents that need repair","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.697211583Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4152026-03-31T18:36:23.147Z{"msg":"sending reconcile request ReconciliationId(2)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.697227133Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4162026-03-31T18:36:23.154Z{"msg":"sending reconcile request ReconciliationId(6)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.709224072Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4172026-03-31T18:36:23.157Z{"msg":"sending reconcile request ReconciliationId(10)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.711306979Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4182026-03-31T18:36:23.160Z{"msg":"sending reconcile request ReconciliationId(14)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.713388786Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4192026-03-31T18:36:23.160Z{"msg":"sending reconcile request ReconciliationId(18)","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.715368929Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4202026-03-31T18:36:23.164Z{"msg":"done with reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.717099384Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"":"downstairs","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4212026-03-31T18:36:23.164Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.717120393Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"0","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4222026-03-31T18:36:23.164Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.717130712Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"1","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4232026-03-31T18:36:23.164Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.717140692Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"client":"2","":"downstairs","session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4242026-03-31T18:36:23.164Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.717150781Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4252026-03-31T18:36:23.164Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.717159961Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4262026-03-31T18:36:23.164Z{"msg":"b02a6ba2-8f02-4e1c-aa53-6cd0ea8b11a6 is now active with session: 9dbd2352-077c-4a5a-9a05-c765e9ae2378","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.71717013Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185,"session_id":"9dbd2352-077c-4a5a-9a05-c765e9ae2378"}
4272026-03-31T18:36:23.164Z{"msg":"The guest has finished waiting for activation with:33","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.71717964Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185}
4282026-03-31T18:36:23.164Z{"msg":"Activated sub_volume b02a6ba2-8f02-4e1c-aa53-6cd0ea8b11a6","v":0,"name":"crucible","level":30,"time":"2026-03-31T18:36:21.717229727Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185}
4292026-03-31T18:36:23.164ZWait for a query_work_queue command to finish before sending IO
4302026-03-31T18:36:23.164ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
4312026-03-31T18:36:23.164ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
4322026-03-31T18:36:23.164ZRead and Verify all blocks (0..50 range:true)
4332026-03-31T18:36:23.188ZWrote out file "/var/tmp/test_up-build/verify_file"
4342026-03-31T18:36:23.188ZVerify test completed
4352026-03-31T18:36:23.191ZWrote out file "/var/tmp/test_up-build/verify_file"
4362026-03-31T18:36:23.191ZCLIENT: Tests done. All submitted work has been ACK'd
4372026-03-31T18:36:23.191Z----------------------------------------------------------------
4382026-03-31T18:36:23.191Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:1
4392026-03-31T18:36:23.191ZStates: Active Active Active
4402026-03-31T18:36:23.191ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
4412026-03-31T18:36:23.191Z 1000 Acked Read 50 Done Done Done false
4422026-03-31T18:36:23.191Z STATES DS:0 DS:1 DS:2 TOTAL
4432026-03-31T18:36:23.191Z Sent 0 0 0 0
4442026-03-31T18:36:23.191Z Done 1 1 1 3
4452026-03-31T18:36:23.191Z Skipped 0 0 0 0
4462026-03-31T18:36:23.191Z Error 0 0 0 0
4472026-03-31T18:36:23.191ZLast Flush: None None None
4482026-03-31T18:36:23.191ZDownstairs last five completed:
4492026-03-31T18:36:23.191ZUpstairs last five completed: 1000
4502026-03-31T18:36:23.191ZCLIENT: Up:0 ds:1 act:3
4512026-03-31T18:36:27.189Z----------------------------------------------------------------
4522026-03-31T18:36:27.189Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:0
4532026-03-31T18:36:27.189ZDownstairs last five completed: 1001 1000
4542026-03-31T18:36:27.189ZUpstairs last five completed: 1001 1000
4552026-03-31T18:36:27.189ZCLIENT: Up:0 ds:0 act:3
4562026-03-31T18:36:27.189ZCLIENT: All crucible jobs finished, exiting program
4572026-03-31T18:36:27.192Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2026-03-31T18:36:25.743634632Z","hostname":"w-01KN2JQH32YFM50QY6QR5YJKAX","pid":1185}
4582026-03-31T18:36:27.196ZRepair part 2 passed
4592026-03-31T18:36:27.197Z/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
4602026-03-31T18:36:27.207ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
4612026-03-31T18:36:27.207Z 0 000-009 32 32 32 1503 1503 1503 F F F
4622026-03-31T18:36:27.207Z 1 010-019 32 32 32 1503 1503 1503 F F F
4632026-03-31T18:36:27.207Z 2 020-029 32 32 32 1503 1503 1503 F F F
4642026-03-31T18:36:27.207Z 3 030-039 32 32 32 1503 1503 1503 F F F
4652026-03-31T18:36:27.207Z 4 040-049 32 32 32 1503 1503 1503 F F F
4662026-03-31T18:36:27.210ZMax gen: 32, Max flush: 1503
4672026-03-31T18:36:27.210Zdump test passed
4682026-03-31T18:36:27.210Z/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
4692026-03-31T18:36:27.219Z Extent 1
4702026-03-31T18:36:27.222ZGEN 32 32 32
4712026-03-31T18:36:27.222ZFLUSH_ID 1503 1503 1503
4722026-03-31T18:36:27.222ZDIRTY
4732026-03-31T18:36:27.222Z
4742026-03-31T18:36:27.222ZBLOCK D0 D1 D2 C0 C1 C2 DIFF
4752026-03-31T18:36:27.222Z010 A A A A A A
4762026-03-31T18:36:27.222Z011 A A A A A A
4772026-03-31T18:36:27.223Z012 A A A A A A
4782026-03-31T18:36:27.223Z013 A A A A A A
4792026-03-31T18:36:27.226Z014 A A A A A A
4802026-03-31T18:36:27.226Z015 A A A A A A
4812026-03-31T18:36:27.226Z016 A A A A A A
4822026-03-31T18:36:27.226Z017 A A A A A A
4832026-03-31T18:36:27.226Z018 A A A A A A
4842026-03-31T18:36:27.226Z019 A A A A A A
4852026-03-31T18:36:27.229Zdump extent test passed
4862026-03-31T18:36:27.229Z/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
4872026-03-31T18:36:27.237ZExtent 2 Block in extent 0 Actual block 20
4882026-03-31T18:36:27.237Z
4892026-03-31T18:36:27.241Z DATA SHA256 VER
4902026-03-31T18:36:27.241Z------ ---------------------------------------------------------------- ---
4912026-03-31T18:36:27.242Z 0 c5b247b6e4af5775b32f68d4f85f51d865293ed1d45b8ebbb832be82d088b2c0 A
4922026-03-31T18:36:27.242Z 1 c5b247b6e4af5775b32f68d4f85f51d865293ed1d45b8ebbb832be82d088b2c0 A
4932026-03-31T18:36:27.242Z 2 c5b247b6e4af5775b32f68d4f85f51d865293ed1d45b8ebbb832be82d088b2c0 A
4942026-03-31T18:36:27.242Z
4952026-03-31T18:36:27.242ZNONCES 0 1 2 DIFF
4962026-03-31T18:36:27.242Z------ ------------------------ ------------------------ ------------------------ -----
4972026-03-31T18:36:27.242Z 0 f2d8a1715dfdd10329500e5c f2d8a1715dfdd10329500e5c f2d8a1715dfdd10329500e5c
4982026-03-31T18:36:27.242Z
4992026-03-31T18:36:27.242Z TAGS 0 1 2 DIFF
5002026-03-31T18:36:27.242Z------ -------------------------------- -------------------------------- -------------------------------- -----
5012026-03-31T18:36:27.242Z 0 8d446d1bd31b37d73e074e935509249b 8d446d1bd31b37d73e074e935509249b 8d446d1bd31b37d73e074e935509249b
5022026-03-31T18:36:27.242Z
5032026-03-31T18:36:27.242ZHASHES 0 1 2 DIFF
5042026-03-31T18:36:27.242Z------ ---------------- ---------------- ---------------- -----
5052026-03-31T18:36:27.243Z
5062026-03-31T18:36:27.243Zdump block test passed
5072026-03-31T18:36:27.243ZInitial upstairs tests have completed, stopping all downstairs
5082026-03-31T18:36:32.261ZCreating 4 larger downstairs regions
5092026-03-31T18:36:32.377ZStarting 4 downstairs
5102026-03-31T18:36:37.382Zdsc restarted at PID: 1198
5112026-03-31T18:36:37.442ZNow do the replace-reconcile test
5122026-03-31T18:36:37.456ZUsing 8840 for the replacement port
5132026-03-31T18:40:01.774ZCompleted test: replace-reconcile
5142026-03-31T18:40:01.774ZNow do the replace-before-active test
5152026-03-31T18:43:18.688ZCompleted test: replace-before-active
5162026-03-31T18:43:18.688ZAll tests have completed, stopping all downstairs
5172026-03-31T18:43:18.704Z
5182026-03-31T18:43:18.704ZAll Tests have passed
5192026-03-31T18:43:18.707Z9:01 Test duration
5202026-03-31T18:43:18.707Z
5212026-03-31T18:43:18.708Zreal 9:00.902056409
5222026-03-31T18:43:18.709Zuser 6:47.114859347
5232026-03-31T18:43:18.709Zsys 5.688107746
5242026-03-31T18:43:18.709Ztrap 0.191939375
5252026-03-31T18:43:18.709Ztflt 0.031161861
5262026-03-31T18:43:18.709Zdflt 0.011975317
5272026-03-31T18:43:18.709Zkflt 0.001059054
5282026-03-31T18:43:18.709Zlock 5:43:41.662335737
5292026-03-31T18:43:18.709Zslp 26:15.305660593
5302026-03-31T18:43:18.709Zlat 29.958401180
5312026-03-31T18:43:18.709Zstop 0.011571416
5322026-03-31T18:43:18.709Z+ echo 'test-up-encrypted ends'
5332026-03-31T18:43:18.709Ztest-up-encrypted ends
5342026-03-31T18:43:23.710Zprocess exited: duration 549539 ms, exit code 0
5352026-03-31T18:43:23.710Zexec warning: : stdio descriptors remain open after task exit; waiting 60 seconds for them to close
5362026-03-31T18:44:23.761Zexec warning: : stdout descriptor may be held open by a background process; giving up!
5372026-03-31T18:44:23.761Zexec warning: : stderr descriptor may be held open by a background process; giving up!
 
5382026-03-31T18:44:23.775Zfound 14 output files
5392026-03-31T18:44:23.775Zuploading: /tmp/test_up-build/dsc-out.txt (47175 bytes)
5402026-03-31T18:44:24.790Zuploaded: /tmp/test_up-build/dsc-out.txt
5412026-03-31T18:44:24.790Zuploading: /tmp/test_up-build/test_up_out.txt (22560359 bytes)
5422026-03-31T18:44:25.944Zuploaded: /tmp/test_up-build/test_up_out.txt
5432026-03-31T18:44:25.948Zuploading: /tmp/test_up-build/dsc/downstairs-8810.txt (2477 bytes)
5442026-03-31T18:44:26.958Zuploaded: /tmp/test_up-build/dsc/downstairs-8810.txt
5452026-03-31T18:44:26.961Zuploading: /tmp/test_up-build/dsc/downstairs-8820.txt (548334 bytes)
5462026-03-31T18:44:27.983Zuploaded: /tmp/test_up-build/dsc/downstairs-8820.txt
5472026-03-31T18:44:27.984Zuploading: /tmp/test_up-build/dsc/downstairs-8830.txt (978635 bytes)
5482026-03-31T18:44:29.007Zuploaded: /tmp/test_up-build/dsc/downstairs-8830.txt
5492026-03-31T18:44:29.007Zuploading: /tmp/test_up-build/dsc/downstairs-8840.txt (543025 bytes)
5502026-03-31T18:44:30.030Zuploaded: /tmp/test_up-build/dsc/downstairs-8840.txt
5512026-03-31T18:44:30.030Zuploading: /tmp/debug/df.txt (1270 bytes)
5522026-03-31T18:44:31.040Zuploaded: /tmp/debug/df.txt
5532026-03-31T18:44:31.044Zuploading: /tmp/debug/dtrace.txt (635528 bytes)
5542026-03-31T18:44:32.063Zuploaded: /tmp/debug/dtrace.txt
5552026-03-31T18:44:32.063Zuploading: /tmp/debug/iostat.txt (180733 bytes)
5562026-03-31T18:44:32.075Zupload warning: file "/tmp/debug/iostat.txt" changed size mid upload: 180733 -> 183415
5572026-03-31T18:44:33.082Zuploaded: /tmp/debug/iostat.txt
5582026-03-31T18:44:33.087Zuploading: /tmp/debug/mpstat.txt (440729 bytes)
5592026-03-31T18:44:33.095Zupload warning: file "/tmp/debug/mpstat.txt" changed size mid upload: 440729 -> 447999
5602026-03-31T18:44:34.103Zuploaded: /tmp/debug/mpstat.txt
5612026-03-31T18:44:34.104Zuploading: /tmp/debug/paging.txt (78116 bytes)
5622026-03-31T18:44:34.111Zupload warning: file "/tmp/debug/paging.txt" changed size mid upload: 78116 -> 79517
5632026-03-31T18:44:35.119Zuploaded: /tmp/debug/paging.txt
5642026-03-31T18:44:35.119Zuploading: /tmp/debug/prstat.txt (850915 bytes)
5652026-03-31T18:44:35.136Zupload warning: file "/tmp/debug/prstat.txt" changed size mid upload: 850915 -> 865134
5662026-03-31T18:44:36.143Zuploaded: /tmp/debug/prstat.txt
5672026-03-31T18:44:36.143Zuploading: /tmp/debug/psrinfo.txt (1528 bytes)
5682026-03-31T18:44:37.152Zuploaded: /tmp/debug/psrinfo.txt
5692026-03-31T18:44:37.156Zuploading: /tmp/debug/upstairs-info.txt (65331 bytes)
5702026-03-31T18:44:38.168Zuploaded: /tmp/debug/upstairs-info.txt