01K7M84X8WCKYFE268K507EWW6: 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: 01K7M85G6Y3BX0FY9BN0BCGHF8

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-10-15T15:55:18.463Zjob dependencies complete; ready to run (waiting for 20 m 11 s)
22025-10-15T15:56:29.471Zjob assigned to worker 01K7M9ANY63QKGFHVJ7KS1VK85 [factory aws, i-0d8f897482c6ba488] (queued for 1 m 11 s)
32025-10-15T15:56:37.956Zdownloading input: /input/build/work/bins/crucible-downstairs.gz
42025-10-15T15:56:39.432Zdownloaded input: /input/build/work/bins/crucible-downstairs.gz
52025-10-15T15:56:39.432Zdownloading input: /input/build/work/bins/crucible-hammer.gz
62025-10-15T15:56:41.236Zdownloaded input: /input/build/work/bins/crucible-hammer.gz
72025-10-15T15:56:41.236Zdownloading input: /input/build/work/bins/crutest.gz
82025-10-15T15:56:42.665Zdownloaded input: /input/build/work/bins/crutest.gz
92025-10-15T15:56:42.666Zdownloading input: /input/build/work/bins/dsc.gz
102025-10-15T15:56:43.737Zdownloaded input: /input/build/work/bins/dsc.gz
112025-10-15T15:56:43.741Zdownloading input: /input/build/work/scripts/perf-downstairs-tick.d
122025-10-15T15:56:43.761Zdownloaded input: /input/build/work/scripts/perf-downstairs-tick.d
132025-10-15T15:56:43.761Zdownloading input: /input/build/work/scripts/test_ds.sh
142025-10-15T15:56:43.783Zdownloaded input: /input/build/work/scripts/test_ds.sh
152025-10-15T15:56:43.783Zdownloading input: /input/build/work/scripts/test_live_repair.sh
162025-10-15T15:56:43.803Zdownloaded input: /input/build/work/scripts/test_live_repair.sh
172025-10-15T15:56:43.803Zdownloading input: /input/build/work/scripts/test_repair.sh
182025-10-15T15:56:43.824Zdownloaded input: /input/build/work/scripts/test_repair.sh
192025-10-15T15:56:43.824Zdownloading input: /input/build/work/scripts/test_replay.sh
202025-10-15T15:56:43.848Zdownloaded input: /input/build/work/scripts/test_replay.sh
212025-10-15T15:56:43.848Zdownloading input: /input/build/work/scripts/test_up.sh
222025-10-15T15:56:43.868Zdownloaded input: /input/build/work/scripts/test_up.sh
232025-10-15T15:56:43.868Zdownloading input: /input/build/work/scripts/upstairs_info.d
242025-10-15T15:56:43.891Zdownloaded input: /input/build/work/scripts/upstairs_info.d
252025-10-15T15:56:43.896Zdownloading input: /input/build/tmp/cargo-test-out.log
262025-10-15T15:56:44.633Zdownloaded input: /input/build/tmp/cargo-test-out.log
 
272025-10-15T15:56:44.633Zstarting task 0: "setup"
282025-10-15T15:56:44.642Z++ uname -s
292025-10-15T15:56:44.646Z+ kern=SunOS
302025-10-15T15:56:44.646Z+ build_user=build
312025-10-15T15:56:44.646Z+ build_uid=12345
322025-10-15T15:56:44.646Z+ work_dir=/work
332025-10-15T15:56:44.647Z+ input_dir=/input
342025-10-15T15:56:44.647Z+ [[ 0 == 12345 ]]
352025-10-15T15:56:44.647Z+ case "$kern" in
362025-10-15T15:56:44.647Z+ groupadd -g 12345 build
372025-10-15T15:56:44.651Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
382025-10-15T15:56:46.657Z+ zfs create -o mountpoint=/work rpool/work
392025-10-15T15:56:46.996Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
402025-10-15T15:56:47.000Z+ home_fs=zfs
412025-10-15T15:56:47.000Z+ [[ zfs == autofs ]]
422025-10-15T15:56:47.001Z+ mkdir -p /home/build
432025-10-15T15:56:47.005Z+ chown build:build /home/build /work
442025-10-15T15:56:49.005Z+ chmod 0700 /home/build /work
452025-10-15T15:56:49.008Zprocess exited: duration 4373 ms, exit code 0
 
462025-10-15T15:56:49.015Zstarting task 1: "authentication"
472025-10-15T15:56:49.040Zprocess exited: duration 23 ms, exit code 0
 
482025-10-15T15:56:49.046Zstarting task 2: "build"
492025-10-15T15:56:49.052Z+ banner cores
502025-10-15T15:56:49.055Z
512025-10-15T15:56:49.055Z #### #### ##### ###### ####
522025-10-15T15:56:49.055Z # # # # # # # #
532025-10-15T15:56:49.055Z # # # # # ##### ####
542025-10-15T15:56:49.056Z # # # ##### # #
552025-10-15T15:56:49.056Z # # # # # # # # #
562025-10-15T15:56:49.056Z #### #### # # ###### ####
572025-10-15T15:56:49.056Z
582025-10-15T15:56:49.061Z+ pfexec coreadm -i /tmp/core.%f.%p -g /tmp/core.%f.%p -e global -e log -e proc-setid -e global-setid
592025-10-15T15:56:49.065Z+ echo 'input bins dir contains:'
602025-10-15T15:56:49.068Zinput bins dir contains:
612025-10-15T15:56:49.069Z+ ls -ltr /input/build/work/bins
622025-10-15T15:56:49.069Ztotal 943989
632025-10-15T15:56:49.069Z-rw-r--r-- 1 root root 141059631 Oct 15 15:56 crucible-downstairs.gz
642025-10-15T15:56:49.069Z-rw-r--r-- 1 root root 134091245 Oct 15 15:56 crucible-hammer.gz
652025-10-15T15:56:49.069Z-rw-r--r-- 1 root root 139135996 Oct 15 15:56 crutest.gz
662025-10-15T15:56:49.069Z-rw-r--r-- 1 root root 68719697 Oct 15 15:56 dsc.gz
672025-10-15T15:56:49.069Z+ banner unpack
682025-10-15T15:56:49.073Z
692025-10-15T15:56:49.073Z # # # # ##### ## #### # #
702025-10-15T15:56:49.073Z # # ## # # # # # # # # #
712025-10-15T15:56:49.073Z # # # # # # # # # # ####
722025-10-15T15:56:49.073Z # # # # # ##### ###### # # #
732025-10-15T15:56:49.073Z # # # ## # # # # # # #
742025-10-15T15:56:49.073Z #### # # # # # #### # #
752025-10-15T15:56:49.073Z
762025-10-15T15:56:49.073Z+ mkdir -p /var/tmp/bins
772025-10-15T15:56:49.073Z+ for t in "$input/bins/"*.gz
782025-10-15T15:56:49.080Z++ basename /input/build/work/bins/crucible-downstairs.gz
792025-10-15T15:56:49.080Z+ b=crucible-downstairs.gz
802025-10-15T15:56:49.080Z+ b=crucible-downstairs
812025-10-15T15:56:49.080Z+ gunzip
822025-10-15T15:56:52.040Z+ chmod +x /var/tmp/bins/crucible-downstairs
832025-10-15T15:56:52.045Z+ for t in "$input/bins/"*.gz
842025-10-15T15:56:52.048Z++ basename /input/build/work/bins/crucible-hammer.gz
852025-10-15T15:56:52.048Z+ b=crucible-hammer.gz
862025-10-15T15:56:52.048Z+ b=crucible-hammer
872025-10-15T15:56:52.048Z+ gunzip
882025-10-15T15:56:54.831Z+ chmod +x /var/tmp/bins/crucible-hammer
892025-10-15T15:56:54.835Z+ for t in "$input/bins/"*.gz
902025-10-15T15:56:54.835Z++ basename /input/build/work/bins/crutest.gz
912025-10-15T15:56:54.838Z+ b=crutest.gz
922025-10-15T15:56:54.838Z+ b=crutest
932025-10-15T15:56:54.838Z+ gunzip
942025-10-15T15:56:57.803Z+ chmod +x /var/tmp/bins/crutest
952025-10-15T15:56:57.806Z+ for t in "$input/bins/"*.gz
962025-10-15T15:56:57.806Z++ basename /input/build/work/bins/dsc.gz
972025-10-15T15:56:57.811Z+ b=dsc.gz
982025-10-15T15:56:57.811Z+ b=dsc
992025-10-15T15:56:57.811Z+ gunzip
1002025-10-15T15:56:59.236Z+ chmod +x /var/tmp/bins/dsc
1012025-10-15T15:56:59.255Z+ export BINDIR=/var/tmp/bins
1022025-10-15T15:56:59.255Z+ BINDIR=/var/tmp/bins
1032025-10-15T15:56:59.255Z+ export RUST_BACKTRACE=1
1042025-10-15T15:56:59.255Z+ RUST_BACKTRACE=1
1052025-10-15T15:56:59.255Z+ jobpid=1157
1062025-10-15T15:56:59.255Z+ echo 'Setup debug logging'
1072025-10-15T15:56:59.255ZSetup debug logging
1082025-10-15T15:56:59.255Z+ mkdir /tmp/debug
1092025-10-15T15:56:59.255Z+ sleep 3600
1102025-10-15T15:56:59.255Z+ psrinfo -v
1112025-10-15T15:56:59.259Z+ df -h
1122025-10-15T15:56:59.259Z+ prstat -d d -mLc 1
1132025-10-15T15:56:59.259Z+ iostat -T d -xn 1
1142025-10-15T15:56:59.259Z+ mpstat -T d 1
1152025-10-15T15:56:59.259Z+ vmstat -T d -p 1
1162025-10-15T15:56:59.259Z+ pfexec dtrace -Z -s /input/build/work/scripts/perf-downstairs-tick.d
1172025-10-15T15:56:59.259Z+ banner test_up_encrypted
1182025-10-15T15:56:59.259Z+ pfexec dtrace -Z -s /input/build/work/scripts/upstairs_info.d
1192025-10-15T15:56:59.259Z
1202025-10-15T15:56:59.259Z ##### ###### #### ##### # # ##### ###### # #
1212025-10-15T15:56:59.259Z # # # # # # # # # ## #
1222025-10-15T15:56:59.259Z # ##### #### # # # # # ##### # # #
1232025-10-15T15:56:59.259Z # # # # # # ##### # # # #
1242025-10-15T15:56:59.259Z # # # # # # # # # # ##
1252025-10-15T15:56:59.259Z # ###### #### # ####### #### # ####### ###### # #
1262025-10-15T15:56:59.259Z
1272025-10-15T15:56:59.259Z+ ptime -m bash /input/build/work/scripts/test_up.sh -N encrypted
1282025-10-15T15:56:59.271Z/input/build/work
1292025-10-15T15:56:59.285ZTurn off color for downstairs dump
1302025-10-15T15:56:59.303ZUpstairs using key: biLigfZqlOa4q/iRWxr6zQyYpHX0FE7YkH72EjGE3F8=
1312025-10-15T15:56:59.306Zdsc output goes to /tmp/test_up-build/dsc-out.txt
1322025-10-15T15:56:59.306ZCreating 3 downstairs regions
1332025-10-15T15:56:59.634ZStarting 3 downstairs
1342025-10-15T15:56:59.637Zdsc started at PID: 1203
1352025-10-15T15:57:04.834ZDisable automatic restart on all downstairs
1362025-10-15T15:57:04.894Z
1372025-10-15T15:57:04.894ZBegin tests, output goes to /tmp/test_up-build/test_up_out.txt
1382025-10-15T15:57:04.898ZRunning test: span
1392025-10-15T15:57:09.077ZCompleted test: span
1402025-10-15T15:57:14.085ZRunning test: big
1412025-10-15T15:57:18.412ZCompleted test: big
1422025-10-15T15:57:23.420ZRunning test: dep
1432025-10-15T15:58:19.152ZCompleted test: dep
1442025-10-15T15:58:21.018ZRunning test: balloon
1452025-10-15T15:59:02.112ZCompleted test: balloon
1462025-10-15T15:59:07.119ZRunning test: deactivate
1472025-10-15T15:59:11.788ZCompleted test: deactivate
1482025-10-15T15:59:16.795ZRunning hammer
1492025-10-15T15:59:34.895ZRun repair tests
1502025-10-15T15:59:34.904Z/var/tmp/bins/crutest fill -g 31 -q --key biLigfZqlOa4q/iRWxr6zQyYpHX0FE7YkH72EjGE3F8= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file
1512025-10-15T15:59:34.961Z{"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-10-15T15:59:33.369876838Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"task":"crutest"}
1522025-10-15T15:59:34.990Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.370491297Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"task":"crutest"}
1532025-10-15T15:59:34.990Z{"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-10-15T15:59:33.37238612Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"task":"crutest"}
1542025-10-15T15:59:34.990Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.372612564Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240}
1552025-10-15T15:59:34.990Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"13b1577b584ca0dbd09b897d333d5c2b128ce008\",\n git_commit_timestamp: \"2025-10-15T15:33:57.000000000Z\",\n git_branch: \"mkeeter/check-hashes\",\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-10-15T15:59:33.372664221Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240}
1562025-10-15T15:59:34.990Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.372687859Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240}
1572025-10-15T15:59:34.990Z{"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":"2025-10-15T15:59:33.372709968Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240}
1582025-10-15T15:59:34.990Z{"msg":"Crucible 521a1d4d-39a2-4747-b1a2-71f58b56df45 has session id: 98d62a6a-1ef3-409c-9e77-aa99607ed6d1","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.37327528Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1592025-10-15T15:59:34.991Z{"msg":"Upstairs opts: Upstairs UUID: 521a1d4d-39a2-4747-b1a2-71f58b56df45, 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":"2025-10-15T15:59:33.373337116Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1602025-10-15T15:59:34.991Z{"msg":"Crucible stats registered with UUID: 521a1d4d-39a2-4747-b1a2-71f58b56df45","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.373378833Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1612025-10-15T15:59:34.991Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-10-15T15:59:33.373414591Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1622025-10-15T15:59:34.991Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.373583869Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"io task","client":"0","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1632025-10-15T15:59:34.991Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.373643265Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"io task","client":"1","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1642025-10-15T15:59:34.991Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.373685312Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"io task","client":"2","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1652025-10-15T15:59:34.991Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374239085Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"task":"crutest"}
1662025-10-15T15:59:34.991Z{"msg":"The guest has requested activation with gen:31","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374292952Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240}
1672025-10-15T15:59:34.991Z{"msg":"521a1d4d-39a2-4747-b1a2-71f58b56df45 active request set","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374323669Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1682025-10-15T15:59:34.991Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374364077Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"client":"0","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1692025-10-15T15:59:34.991Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374417223Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"client":"1","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1702025-10-15T15:59:34.991Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.3744682Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"client":"2","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1712025-10-15T15:59:34.991Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374500038Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"io task","client":"0","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1722025-10-15T15:59:34.991Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374551264Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"io task","client":"2","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1732025-10-15T15:59:34.991Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374590602Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"io task","client":"1","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1742025-10-15T15:59:34.991Z{"msg":"ds_connection connected from Ok(127.0.0.1:47427)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.37462031Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"io task","client":"0","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1752025-10-15T15:59:34.991Z{"msg":"ds_connection connected from Ok(127.0.0.1:39147)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374656677Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"io task","client":"2","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1762025-10-15T15:59:34.991Z{"msg":"ds_connection connected from Ok(127.0.0.1:46803)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.374686525Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"io task","client":"1","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1772025-10-15T15:59:34.991Z{"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-10-15T15:59:33.376113799Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"client":"0","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1782025-10-15T15:59:34.991Z{"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-10-15T15:59:33.376168686Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"client":"2","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1792025-10-15T15:59:34.991Z{"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-10-15T15:59:33.376213523Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"client":"1","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1802025-10-15T15:59:34.991Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376610276Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1812025-10-15T15:59:34.992Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376647393Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1822025-10-15T15:59:34.992Z{"msg":"[0]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376672052Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1832025-10-15T15:59:34.992Z{"msg":"[0]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.37669864Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1842025-10-15T15:59:34.992Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376716829Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1852025-10-15T15:59:34.992Z{"msg":"[1]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376741617Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1862025-10-15T15:59:34.992Z{"msg":"[1]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376758686Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1872025-10-15T15:59:34.992Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376782564Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1882025-10-15T15:59:34.992Z{"msg":"[2]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376799993Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1892025-10-15T15:59:34.992Z{"msg":"[2]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376816542Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1902025-10-15T15:59:34.992Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.37684122Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1912025-10-15T15:59:34.992Z{"msg":"Max found gen is 26","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376857709Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1922025-10-15T15:59:34.992Z{"msg":"Generation requested: 31 >= found:26","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376875908Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1932025-10-15T15:59:34.992Z{"msg":"Next flush: 1501","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376916345Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1942025-10-15T15:59:34.992Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376941254Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"":"downstairs","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1952025-10-15T15:59:34.992Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.376971892Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1962025-10-15T15:59:34.992Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.37698843Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"client":"0","":"downstairs","session_id":"Wait for a query_work_queue command to finish before sending IO
1972025-10-15T15:59:34.992Z98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1982025-10-15T15:59:34.992Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.377035647Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"client":"1","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
1992025-10-15T15:59:34.992Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.377062985Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"client":"2","":"downstairs","session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
2002025-10-15T15:59:34.993Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.377080624Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
2012025-10-15T15:59:34.993Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.377097303Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
2022025-10-15T15:59:34.993Z{"msg":"521a1d4d-39a2-4747-b1a2-71f58b56df45 is now active with session: 98d62a6a-1ef3-409c-9e77-aa99607ed6d1","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.377118022Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
2032025-10-15T15:59:34.993Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.377155239Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240,"session_id":"98d62a6a-1ef3-409c-9e77-aa99607ed6d1"}
2042025-10-15T15:59:34.993Z{"msg":"The guest has finished waiting for activation with:31","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.377185267Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240}
2052025-10-15T15:59:34.993Z{"msg":"Activated sub_volume 521a1d4d-39a2-4747-b1a2-71f58b56df45","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:33.377207386Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1240}
2062025-10-15T15:59:34.993ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2072025-10-15T15:59:34.993ZFill test
2082025-10-15T15:59:35.008ZRead and Verify all blocks (0..50 range:false)
2092025-10-15T15:59:35.040ZWrote out file "/var/tmp/test_up-build/verify_file"
2102025-10-15T15:59:35.040ZCLIENT: Tests done. All submitted work has been ACK'd
2112025-10-15T15:59:35.046Z----------------------------------------------------------------
2122025-10-15T15:59:35.046Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:1
2132025-10-15T15:59:35.046ZStates: Active Active Active
2142025-10-15T15:59:35.046ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2152025-10-15T15:59:35.046Z 1002 Acked Read 50 Done Done Done false
2162025-10-15T15:59:35.047Z STATES DS:0 DS:1 DS:2 TOTAL
2172025-10-15T15:59:35.047Z Sent 0 0 0 0
2182025-10-15T15:59:35.047Z Done 1 1 1 3
2192025-10-15T15:59:35.047Z Skipped 0 0 0 0
2202025-10-15T15:59:35.047Z Error 0 0 0 0
2212025-10-15T15:59:35.047ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
2222025-10-15T15:59:35.047ZDownstairs last five completed: 1001 1000
2232025-10-15T15:59:35.047ZUpstairs last five completed: 1002 1001 1000
2242025-10-15T15:59:35.047ZCLIENT: Up:0 ds:1 act:3
2252025-10-15T15:59:39.038Z----------------------------------------------------------------
2262025-10-15T15:59:39.038Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:0
2272025-10-15T15:59:39.038ZDownstairs last five completed: 1003 1002 1001 1000
2282025-10-15T15:59:39.038ZUpstairs last five completed: 1003 1002 1001 1000
2292025-10-15T15:59:39.038ZCLIENT: Up:0 ds:0 act:3
2302025-10-15T15:59:39.038ZCLIENT: All crucible jobs finished, exiting program
2312025-10-15T15:59:39.049ZRepair setup passed
2322025-10-15T15:59:39.055ZCopy the region for /var/tmp/test_up-build/8830
2332025-10-15T15:59:39.059Zcp -r /var/tmp/test_up-build/8830 /var/tmp/test_up-build/previous
2342025-10-15T15:59:39.059Z/var/tmp/bins/crutest fill -g 32 -q --key biLigfZqlOa4q/iRWxr6zQyYpHX0FE7YkH72EjGE3F8= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
2352025-10-15T15:59:39.113Z{"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-10-15T15:59:37.533782841Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"task":"crutest"}
2362025-10-15T15:59:39.135Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.534378571Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"task":"crutest"}
2372025-10-15T15:59:39.135Z{"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-10-15T15:59:37.536205249Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"task":"crutest"}
2382025-10-15T15:59:39.135Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.536393646Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246}
2392025-10-15T15:59:39.135Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"13b1577b584ca0dbd09b897d333d5c2b128ce008\",\n git_commit_timestamp: \"2025-10-15T15:33:57.000000000Z\",\n git_branch: \"mkeeter/check-hashes\",\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-10-15T15:59:37.536452562Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246}
2402025-10-15T15:59:39.135Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.53648037Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246}
2412025-10-15T15:59:39.135Z{"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":"2025-10-15T15:59:37.536509248Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246}
2422025-10-15T15:59:39.135Z{"msg":"Crucible aeb95f3b-a414-41b7-875a-3983962b0d1f has session id: 0ce70e56-319b-4cc7-a19d-7b4e73445f8d","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.537029783Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2432025-10-15T15:59:39.135Z{"msg":"Upstairs opts: Upstairs UUID: aeb95f3b-a414-41b7-875a-3983962b0d1f, 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":"2025-10-15T15:59:37.537101088Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2442025-10-15T15:59:39.135Z{"msg":"Crucible stats registered with UUID: aeb95f3b-a414-41b7-875a-3983962b0d1f","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.537128996Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2452025-10-15T15:59:39.135Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-10-15T15:59:37.537155914Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2462025-10-15T15:59:39.135Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.537306764Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"io task","client":"1","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2472025-10-15T15:59:39.136Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.53736502Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"io task","client":"0","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2482025-10-15T15:59:39.136Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.537402978Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"io task","client":"2","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2492025-10-15T15:59:39.136Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.53796449Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"task":"crutest"}
2502025-10-15T15:59:39.136Z{"msg":"The guest has requested activation with gen:32","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.538075973Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246}
2512025-10-15T15:59:39.136Z{"msg":"aeb95f3b-a414-41b7-875a-3983962b0d1f active request set","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.538103961Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2522025-10-15T15:59:39.136Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.53812105Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"client":"0","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2532025-10-15T15:59:39.136Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.538155657Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"client":"1","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2542025-10-15T15:59:39.136Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.538186445Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"client":"2","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2552025-10-15T15:59:39.136Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.538220283Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"io task","client":"2","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2562025-10-15T15:59:39.136Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.53826447Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"io task","client":"0","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2572025-10-15T15:59:39.136Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.538313017Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"io task","client":"1","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2582025-10-15T15:59:39.136Z{"msg":"ds_connection connected from Ok(127.0.0.1:35871)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.538362404Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"io task","client":"2","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2592025-10-15T15:59:39.136Z{"msg":"ds_connection connected from Ok(127.0.0.1:50090)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.538405241Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"io task","client":"1","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2602025-10-15T15:59:39.136Z{"msg":"ds_connection connected from Ok(127.0.0.1:42875)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.538580169Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"io task","client":"0","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2612025-10-15T15:59:39.136Z{"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-10-15T15:59:37.539806696Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"client":"1","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2622025-10-15T15:59:39.136Z{"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-10-15T15:59:37.539860593Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"client":"2","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2632025-10-15T15:59:39.136Z{"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-10-15T15:59:37.53989935Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"client":"0","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2642025-10-15T15:59:39.136Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540234218Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2652025-10-15T15:59:39.136Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540272355Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2662025-10-15T15:59:39.136Z{"msg":"[0]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540290604Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2672025-10-15T15:59:39.136Z{"msg":"[0]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540316412Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2682025-10-15T15:59:39.137Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540334461Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2692025-10-15T15:59:39.137Z{"msg":"[1]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540359309Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2702025-10-15T15:59:39.137Z{"msg":"[1]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540384058Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2712025-10-15T15:59:39.137Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540407966Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2722025-10-15T15:59:39.137Z{"msg":"[2]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540426505Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2732025-10-15T15:59:39.137Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540449773Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2742025-10-15T15:59:39.137Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540467712Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2752025-10-15T15:59:39.137Z{"msg":"Max found gen is 32","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.54049035Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2762025-10-15T15:59:39.137Z{"msg":"Generation requested: 32 >= found:32","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540507329Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2772025-10-15T15:59:39.137Z{"msg":"Next flush: 1502","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540534427Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2782025-10-15T15:59:39.137Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540550497Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"":"downstairs","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2792025-10-15T15:59:39.137Z{"msg":"Wait for a query_work_queue command to finish before sending IO
2802025-10-15T15:59:39.137ZNo downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540574505Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2812025-10-15T15:59:39.137Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540590484Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"client":"0","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2822025-10-15T15:59:39.137Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540607093Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"client":"1","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2832025-10-15T15:59:39.138Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540630271Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"client":"2","":"downstairs","session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2842025-10-15T15:59:39.138Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.54064753Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2852025-10-15T15:59:39.138Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540670489Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2862025-10-15T15:59:39.138Z{"msg":"aeb95f3b-a414-41b7-875a-3983962b0d1f is now active with session: 0ce70e56-319b-4cc7-a19d-7b4e73445f8d","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540688747Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2872025-10-15T15:59:39.138Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540704286Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246,"session_id":"0ce70e56-319b-4cc7-a19d-7b4e73445f8d"}
2882025-10-15T15:59:39.138Z{"msg":"The guest has finished waiting for activation with:32","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540727155Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246}
2892025-10-15T15:59:39.138Z{"msg":"Activated sub_volume aeb95f3b-a414-41b7-875a-3983962b0d1f","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:37.540741284Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246}
2902025-10-15T15:59:39.138ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2912025-10-15T15:59:39.138ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
2922025-10-15T15:59:39.138ZFill test
2932025-10-15T15:59:39.160ZRead and Verify all blocks (0..50 range:false)
2942025-10-15T15:59:39.202ZWrote out file "/var/tmp/test_up-build/verify_file"
2952025-10-15T15:59:39.202ZCLIENT: Tests done. All submitted work has been ACK'd
2962025-10-15T15:59:39.212Z----------------------------------------------------------------
2972025-10-15T15:59:39.212Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:1
2982025-10-15T15:59:39.212ZStates: Active Active Active
2992025-10-15T15:59:39.212ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
3002025-10-15T15:59:39.212Z 1002 Acked Read 50 Sent Done Sent false
3012025-10-15T15:59:39.212Z STATES DS:0 DS:1 DS:2 TOTAL
3022025-10-15T15:59:39.212Z Sent 1 0 1 2
3032025-10-15T15:59:39.212Z Done 0 1 0 1
3042025-10-15T15:59:39.212Z Skipped 0 0 0 0
3052025-10-15T15:59:39.212Z Error 0 0 0 0
3062025-10-15T15:59:39.212ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
3072025-10-15T15:59:39.212ZDownstairs last five completed: 1001 1000
3082025-10-15T15:59:39.213ZUpstairs last five completed: 1002 1001 1000
3092025-10-15T15:59:39.213ZCLIENT: Up:0 ds:1 act:3
3102025-10-15T15:59:43.200Z----------------------------------------------------------------
3112025-10-15T15:59:43.200Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:0
3122025-10-15T15:59:43.200ZDownstairs last five completed: 1003 1002 1001 1000
3132025-10-15T15:59:43.200ZUpstairs last five completed: 1003 1002 1001 1000
3142025-10-15T15:59:43.200ZCLIENT: Up:0 ds:0 act:3
3152025-10-15T15:59:43.200ZCLIENT: All crucible jobs finished, exiting program
3162025-10-15T15:59:43.203Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-10-15T15:59:41.620440294Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1246}
3172025-10-15T15:59:43.207ZRepair part 1 passed
3182025-10-15T15:59:43.208Z
3192025-10-15T15:59:43.208ZKill the current downstairs
3202025-10-15T15:59:43.377ZDownstairs 2 stopped
3212025-10-15T15:59:43.377Zmv /var/tmp/test_up-build/8830 /var/tmp/test_up-build/new
3222025-10-15T15:59:43.386ZNow put back the original so we have a mismatch
3232025-10-15T15:59:43.386Zmv /var/tmp/test_up-build/previous /var/tmp/test_up-build/8830
3242025-10-15T15:59:43.386ZRestart downstairs with old directory
3252025-10-15T15:59:43.449Z/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
3262025-10-15T15:59:43.467ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
3272025-10-15T15:59:43.468Z 0 000-009 32 32 31 1502 1502 1501 F F F <---
3282025-10-15T15:59:43.468Z 1 010-019 32 32 31 1502 1502 1501 F F F <---
3292025-10-15T15:59:43.468Z 2 020-029 32 32 31 1502 1502 1501 F F F <---
3302025-10-15T15:59:43.468Z 3 030-039 32 32 31 1502 1502 1501 F F F <---
3312025-10-15T15:59:43.468Z 4 040-049 32 32 31 1502 1502 1501 F F F <---
3322025-10-15T15:59:43.468ZMax gen: 32, Max flush: 1502
3332025-10-15T15:59:43.702ZError: Difference in extent metadata found!
3342025-10-15T15:59:43.702Z
3352025-10-15T15:59:43.702ZStack backtrace:
3362025-10-15T15:59:43.702Z 0: anyhow::error::<impl anyhow::Error>::msg
3372025-10-15T15:59:43.702Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/backtrace.rs:27:14
3382025-10-15T15:59:43.702Z 1: anyhow::__private::format_err
3392025-10-15T15:59:43.702Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/lib.rs:695:13
3402025-10-15T15:59:43.702Z 2: crucible_downstairs::dump::dump_region
3412025-10-15T15:59:43.702Z at /work/oxidecomputer/crucible/downstairs/src/dump.rs:356:9
3422025-10-15T15:59:43.721Zdump test found error as expected
3432025-10-15T15:59:43.725Z
3442025-10-15T15:59:43.726Z
3452025-10-15T15:59:43.726Z/var/tmp/bins/crutest verify --range -g 33 -q --key biLigfZqlOa4q/iRWxr6zQyYpHX0FE7YkH72EjGE3F8= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
3462025-10-15T15:59:43.779Z{"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-10-15T15:59:42.198764862Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"task":"crutest"}
3472025-10-15T15:59:43.783Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.19939666Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"task":"crutest"}
3482025-10-15T15:59:43.783Z{"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-10-15T15:59:42.201248236Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"task":"crutest"}
3492025-10-15T15:59:43.783Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.201458111Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254}
3502025-10-15T15:59:43.783Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"13b1577b584ca0dbd09b897d333d5c2b128ce008\",\n git_commit_timestamp: \"2025-10-15T15:33:57.000000000Z\",\n git_branch: \"mkeeter/check-hashes\",\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-10-15T15:59:42.201507428Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254}
3512025-10-15T15:59:43.783Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.201530477Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254}
3522025-10-15T15:59:43.783Z{"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":"2025-10-15T15:59:42.201552745Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254}
3532025-10-15T15:59:43.783Z{"msg":"Crucible ae1b073c-9157-4772-9093-a2546c7644c3 has session id: 642110bb-9c55-4812-b7ca-b31188a6c148","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.202167744Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3542025-10-15T15:59:43.783Z{"msg":"Upstairs opts: Upstairs UUID: ae1b073c-9157-4772-9093-a2546c7644c3, 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":"2025-10-15T15:59:42.202237739Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3552025-10-15T15:59:43.783Z{"msg":"Crucible stats registered with UUID: ae1b073c-9157-4772-9093-a2546c7644c3","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.202297845Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3562025-10-15T15:59:43.783Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-10-15T15:59:42.202331713Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3572025-10-15T15:59:43.783Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.202426646Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"0","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3582025-10-15T15:59:43.783Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.202483133Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"1","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3592025-10-15T15:59:43.784Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.20252688Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3602025-10-15T15:59:43.788Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203177626Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"task":"crutest"}
3612025-10-15T15:59:43.788Z{"msg":"The guest has requested activation with gen:33","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203209284Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254}
3622025-10-15T15:59:43.788Z{"msg":"ae1b073c-9157-4772-9093-a2546c7644c3 active request set","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203306827Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3632025-10-15T15:59:43.788Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203338385Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"0","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3642025-10-15T15:59:43.788Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203357104Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"1","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3652025-10-15T15:59:43.788Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203392081Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3662025-10-15T15:59:43.788Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.20341487Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3672025-10-15T15:59:43.788Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203432399Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"0","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3682025-10-15T15:59:43.788Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203457297Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"1","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3692025-10-15T15:59:43.788Z{"msg":"ds_connection connected from Ok(127.0.0.1:35893)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203547921Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"0","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3702025-10-15T15:59:43.788Z{"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-10-15T15:59:42.203614526Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3712025-10-15T15:59:43.788Z{"msg":"ds_connection connected from Ok(127.0.0.1:45923)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203661603Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"1","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3722025-10-15T15:59:43.788Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2025-10-15T15:59:42.20371727Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3732025-10-15T15:59:43.789Z{"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-10-15T15:59:42.20386136Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3742025-10-15T15:59:43.789Z{"msg":"sleeping for 10s before connecting","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203901497Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3752025-10-15T15:59:43.789Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.203923126Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3762025-10-15T15:59:43.789Z{"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-10-15T15:59:42.204837284Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"1","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3772025-10-15T15:59:43.789Z{"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-10-15T15:59:42.204925738Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"0","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3782025-10-15T15:59:43.789Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.205263846Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3792025-10-15T15:59:43.789Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:42.205308433Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3802025-10-15T15:59:53.787Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.205895752Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3812025-10-15T15:59:53.799Z{"msg":"ds_connection connected from Ok(127.0.0.1:45376)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.206036293Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"io task","client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3822025-10-15T15:59:53.799Z{"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-10-15T15:59:52.207395661Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3832025-10-15T15:59:53.799Z{"msg":"[0]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.207797464Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3842025-10-15T15:59:53.799Z{"msg":"[0]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.207848421Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3852025-10-15T15:59:53.799Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.207882599Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3862025-10-15T15:59:53.799Z{"msg":"[1]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.207913897Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3872025-10-15T15:59:53.799Z{"msg":"[1]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.207943045Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3882025-10-15T15:59:53.800Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.207965533Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3892025-10-15T15:59:53.800Z{"msg":"[2]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.20801583Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3902025-10-15T15:59:53.800Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208058947Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3912025-10-15T15:59:53.800Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208077735Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3922025-10-15T15:59:53.800Z{"msg":"Max found gen is 33","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208101094Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3932025-10-15T15:59:53.800Z{"msg":"Generation requested: 33 >= found:33","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208118383Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3942025-10-15T15:59:53.800Z{"msg":"Next flush: 1503","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208141001Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3952025-10-15T15:59:53.800Z{"msg":"extent 0 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.20816625Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3962025-10-15T15:59:53.800Z{"msg":"extent:0 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208198558Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3972025-10-15T15:59:53.800Z{"msg":"found dest for source 0 for extent at index 0 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208223866Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3982025-10-15T15:59:53.800Z{"msg":"extent 1 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208249924Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
3992025-10-15T15:59:53.800Z{"msg":"extent:1 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208280932Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4002025-10-15T15:59:53.800Z{"msg":"found dest for source 0 for extent at index 1 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208300011Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4012025-10-15T15:59:53.800Z{"msg":"extent 2 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208331829Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4022025-10-15T15:59:53.800Z{"msg":"extent:2 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208364816Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4032025-10-15T15:59:53.800Z{"msg":"found dest for source 0 for extent at index 2 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208390394Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4042025-10-15T15:59:53.800Z{"msg":"extent 3 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208421832Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4052025-10-15T15:59:53.800Z{"msg":"extent:3 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.20845274Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4062025-10-15T15:59:53.800Z{"msg":"found dest for source 0 for extent at index 3 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208477289Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4072025-10-15T15:59:53.800Z{"msg":"extent 4 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208503087Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4082025-10-15T15:59:53.800Z{"msg":"extent:4 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1502, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1501, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208533835Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4092025-10-15T15:59:53.800Z{"msg":"found dest for source 0 for extent at index 4 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208558663Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"mend","":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4102025-10-15T15:59:53.801Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208595991Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"0","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4112025-10-15T15:59:53.801Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208623089Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"1","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4122025-10-15T15:59:53.801Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208645357Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4132025-10-15T15:59:53.801Z{"msg":"Full repair list: {ExtentId(0): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(2): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(1): 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)] }}","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208694894Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4142025-10-15T15:59:53.801Z{"msg":"Task list: [ReconcileIO { id: ReconciliationId(0), op: ExtentFlush { repair_id: ReconciliationId(0), extent_id: ExtentId(0), client_id: ClientId(0), flush_number: 1503, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(1), op: ExtentClose { repair_id: ReconciliationId(1), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(2), op: ExtentRepair { repair_id: ReconciliationId(2), 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(3), op: ExtentReopen { repair_id: ReconciliationId(3), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(4), op: ExtentFlush { repair_id: ReconciliationId(4), extent_id: ExtentId(2), client_id: ClientId(0), flush_number: 1503, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(5), op: ExtentClose { repair_id: ReconciliationId(5), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(6), op: ExtentRepair { repair_id: ReconciliationId(6), 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(7), op: ExtentReopen { repair_id: ReconciliationId(7), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(8), op: ExtentFlush { repair_id: ReconciliationId(8), extent_id: ExtentId(1), client_id: ClientId(0), flush_number: 1503, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(9), op: ExtentClose { repair_id: ReconciliationId(9), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(10), op: ExtentRepair { repair_id: ReconciliationId(10), 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(11), op: ExtentReopen { repair_id: ReconciliationId(11), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(12), op: ExtentFlush { repair_id: ReconciliationId(12), extent_id: ExtentId(4), client_id: ClientId(0), flush_number: 1503, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(13), op: ExtentClose { repair_id: ReconciliationId(13), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(14), op: ExtentRepair { repair_id: ReconciliationId(14), 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(15), op: ExtentReopen { repair_id: ReconciliationId(15), extent_id: ExtentId(4) }, 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: 1503, 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-10-15T15:59:52.208944237Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4152025-10-15T15:59:53.801Z{"msg":"starting reconciliation 11caacee-30af-401a-aa10-cb476ba76651: found 20 extents that need repair","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.208984435Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4162025-10-15T15:59:53.801Z{"msg":"sending reconcile request ReconciliationId(2)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.20904997Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4172025-10-15T15:59:53.819Z{"msg":"sending reconcile request ReconciliationId(6)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.223083118Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4182025-10-15T15:59:53.819Z{"msg":"sending reconcile request ReconciliationId(10)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.226941548Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4192025-10-15T15:59:53.819Z{"msg":"sending reconcile request ReconciliationId(14)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.230539077Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4202025-10-15T15:59:53.829Z{"msg":"sending reconcile request ReconciliationId(18)","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.234117706Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4212025-10-15T15:59:53.829Z{"msg":"done with reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.237229057Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"":"downstairs","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4222025-10-15T15:59:53.829Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.237275744Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"0","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4232025-10-15T15:59:53.829Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.237309742Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"1","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4242025-10-15T15:59:53.829Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.237345189Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"client":"2","":"downstairs","session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4252025-10-15T15:59:53.829Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.237386957Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4262025-10-15T15:59:53.829Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.237424434Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":"642110bb-9c55-4812-b7ca-b31188a6c148"}
4272025-10-15T15:59:53.829Z{"msg":"ae1b073c-9157-4772-9093-a2546c7644c3 is now active with session: 642110bb-9c55-4812-b7ca-b31188a6c148","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.237455952Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254,"session_id":Wait for a query_work_queue command to finish before sending IO
4282025-10-15T15:59:53.829Z"642110bb-9c55-4812-b7ca-b31188a6c148"}
4292025-10-15T15:59:53.829Z{"msg":"The guest has finished waiting for activation with:33","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.237495079Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254}
4302025-10-15T15:59:53.829Z{"msg":"Activated sub_volume ae1b073c-9157-4772-9093-a2546c7644c3","v":0,"name":"crucible","level":30,"time":"2025-10-15T15:59:52.237519438Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254}
4312025-10-15T15:59:53.829ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
4322025-10-15T15:59:53.829ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
4332025-10-15T15:59:53.829ZRead and Verify all blocks (0..50 range:true)
4342025-10-15T15:59:53.859ZWrote out file "/var/tmp/test_up-build/verify_file"
4352025-10-15T15:59:53.859ZVerify test completed
4362025-10-15T15:59:53.867ZWrote out file "/var/tmp/test_up-build/verify_file"
4372025-10-15T15:59:53.868ZCLIENT: Tests done. All submitted work has been ACK'd
4382025-10-15T15:59:53.868Z----------------------------------------------------------------
4392025-10-15T15:59:53.868Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:1
4402025-10-15T15:59:53.868ZStates: Active Active Active
4412025-10-15T15:59:53.868ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
4422025-10-15T15:59:53.868Z 1000 Acked Read 50 Done Done Done false
4432025-10-15T15:59:53.868Z STATES DS:0 DS:1 DS:2 TOTAL
4442025-10-15T15:59:53.868Z Sent 0 0 0 0
4452025-10-15T15:59:53.868Z Done 1 1 1 3
4462025-10-15T15:59:53.868Z Skipped 0 0 0 0
4472025-10-15T15:59:53.868Z Error 0 0 0 0
4482025-10-15T15:59:53.868ZLast Flush: None None None
4492025-10-15T15:59:53.868ZDownstairs last five completed:
4502025-10-15T15:59:53.868ZUpstairs last five completed: 1000
4512025-10-15T15:59:53.868ZCLIENT: Up:0 ds:1 act:3
4522025-10-15T15:59:57.861Z----------------------------------------------------------------
4532025-10-15T15:59:57.861Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:0
4542025-10-15T15:59:57.862ZDownstairs last five completed: 1001 1000
4552025-10-15T15:59:57.862ZUpstairs last five completed: 1001 1000
4562025-10-15T15:59:57.862ZCLIENT: Up:0 ds:0 act:3
4572025-10-15T15:59:57.862ZCLIENT: All crucible jobs finished, exiting program
4582025-10-15T15:59:57.872Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-10-15T15:59:56.280041555Z","hostname":"w-01K7M9ANY63QKGFHVJ7KS1VK85","pid":1254}
4592025-10-15T15:59:57.872ZRepair part 2 passed
4602025-10-15T15:59:57.872Z/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
4612025-10-15T15:59:57.885ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
4622025-10-15T15:59:57.885Z 0 000-009 32 32 32 1502 1502 1502 F F F
4632025-10-15T15:59:57.896Z 1 010-019 32 32 32 1502 1502 1502 F F F
4642025-10-15T15:59:57.896Z 2 020-029 32 32 32 1502 1502 1502 F F F
4652025-10-15T15:59:57.896Z 3 030-039 32 32 32 1502 1502 1502 F F F
4662025-10-15T15:59:57.896Z 4 040-049 32 32 32 1502 1502 1502 F F F
4672025-10-15T15:59:57.896ZMax gen: 32, Max flush: 1502
4682025-10-15T15:59:57.896Zdump test passed
4692025-10-15T15:59:57.896Z/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
4702025-10-15T15:59:57.907Z Extent 1
4712025-10-15T15:59:57.907ZGEN 32 32 32
4722025-10-15T15:59:57.907ZFLUSH_ID 1502 1502 1502
4732025-10-15T15:59:57.907ZDIRTY
4742025-10-15T15:59:57.907Z
4752025-10-15T15:59:57.907ZBLOCK D0 D1 D2 C0 C1 C2 DIFF
4762025-10-15T15:59:57.917Z010 A A A A A A
4772025-10-15T15:59:57.917Z011 A A A A A A
4782025-10-15T15:59:57.917Z012 A A A A A A
4792025-10-15T15:59:57.917Z013 A A A A A A
4802025-10-15T15:59:57.917Z014 A A A A A A
4812025-10-15T15:59:57.917Z015 A A A A A A
4822025-10-15T15:59:57.917Z016 A A A A A A
4832025-10-15T15:59:57.917Z017 A A A A A A
4842025-10-15T15:59:57.926Z018 A A A A A A
4852025-10-15T15:59:57.926Z019 A A A A A A
4862025-10-15T15:59:57.926Zdump extent test passed
4872025-10-15T15:59:57.926Z/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
4882025-10-15T15:59:57.940ZExtent 2 Block in extent 0 Actual block 20
4892025-10-15T15:59:57.945Z
4902025-10-15T15:59:57.945Z DATA SHA256 VER
4912025-10-15T15:59:57.945Z------ ---------------------------------------------------------------- ---
4922025-10-15T15:59:57.945Z 0 f3f127e53821b86a98e4538f5f8c09836dc30216d963f7cc624c9c270f53d8b7 A
4932025-10-15T15:59:57.945Z 1 f3f127e53821b86a98e4538f5f8c09836dc30216d963f7cc624c9c270f53d8b7 A
4942025-10-15T15:59:57.945Z 2 f3f127e53821b86a98e4538f5f8c09836dc30216d963f7cc624c9c270f53d8b7 A
4952025-10-15T15:59:57.945Z
4962025-10-15T15:59:57.945ZNONCES 0 1 2 DIFF
4972025-10-15T15:59:57.945Z------ ------------------------ ------------------------ ------------------------ -----
4982025-10-15T15:59:57.945Z 0 513cf02fa2120d30514350e9 513cf02fa2120d30514350e9 513cf02fa2120d30514350e9
4992025-10-15T15:59:57.945Z
5002025-10-15T15:59:57.945Z TAGS 0 1 2 DIFF
5012025-10-15T15:59:57.946Z------ -------------------------------- -------------------------------- -------------------------------- -----
5022025-10-15T15:59:57.946Z 0 eff13a9a08153eafa3a5e08d4637b2d4 eff13a9a08153eafa3a5e08d4637b2d4 eff13a9a08153eafa3a5e08d4637b2d4
5032025-10-15T15:59:57.946Z
5042025-10-15T15:59:57.946ZHASHES 0 1 2 DIFF
5052025-10-15T15:59:57.946Z------ ---------------- ---------------- ---------------- -----
5062025-10-15T15:59:57.947Z
5072025-10-15T15:59:57.952Zdump block test passed
5082025-10-15T15:59:57.952ZInitial upstairs tests have completed, stopping all downstairs
5092025-10-15T16:00:05.452ZCreating 4 larger downstairs regions
5102025-10-15T16:00:05.452ZStarting 4 downstairs
5112025-10-15T16:00:08.204Zdsc restarted at PID: 1267
5122025-10-15T16:00:08.425ZNow do the replace-reconcile test
5132025-10-15T16:00:08.481ZUsing 8840 for the replacement port
5142025-10-15T16:03:41.409ZCompleted test: replace-reconcile
5152025-10-15T16:03:41.412ZNow do the replace-before-active test
5162025-10-15T16:08:04.345ZCompleted test: replace-before-active
5172025-10-15T16:08:04.345ZAll tests have completed, stopping all downstairs
5182025-10-15T16:08:04.349Z
5192025-10-15T16:08:04.349ZAll Tests have passed
5202025-10-15T16:08:04.349Z11:05 Test duration
5212025-10-15T16:08:04.349Z
5222025-10-15T16:08:04.349Zreal 11:04.912903930
5232025-10-15T16:08:04.349Zuser 17:37.104054113
5242025-10-15T16:08:04.349Zsys 16.750823659
5252025-10-15T16:08:04.349Ztrap 0.650807796
5262025-10-15T16:08:04.349Ztflt 0.028754074
5272025-10-15T16:08:04.349Zdflt 0.018393322
5282025-10-15T16:08:04.349Zkflt 0.001210175
5292025-10-15T16:08:04.349Zlock 7:33:27.102709179
5302025-10-15T16:08:04.349Zslp 33:09.426841820
5312025-10-15T16:08:04.349Zlat 1:27.840237040
5322025-10-15T16:08:04.349Zstop 0.020137364
5332025-10-15T16:08:04.349Z+ echo 'test-up-encrypted ends'
5342025-10-15T16:08:04.349Ztest-up-encrypted ends
5352025-10-15T16:08:09.257Zprocess exited: duration 675129 ms, exit code 0
5362025-10-15T16:08:09.257Zexec warning: : stdio descriptors remain open after task exit; waiting 60 seconds for them to close
5372025-10-15T16:09:09.294Zexec warning: : stdout descriptor may be held open by a background process; giving up!
5382025-10-15T16:09:09.294Zexec warning: : stderr descriptor may be held open by a background process; giving up!
 
5392025-10-15T16:09:09.306Zfound 14 output files
5402025-10-15T16:09:09.306Zuploading: /tmp/test_up-build/dsc-out.txt (45635 bytes)
5412025-10-15T16:09:10.318Zuploaded: /tmp/test_up-build/dsc-out.txt
5422025-10-15T16:09:10.328Zuploading: /tmp/test_up-build/test_up_out.txt (21110065 bytes)
5432025-10-15T16:09:11.520Zuploaded: /tmp/test_up-build/test_up_out.txt
5442025-10-15T16:09:11.523Zuploading: /tmp/test_up-build/dsc/downstairs-8810.txt (2497 bytes)
5452025-10-15T16:09:12.530Zuploaded: /tmp/test_up-build/dsc/downstairs-8810.txt
5462025-10-15T16:09:12.530Zuploading: /tmp/test_up-build/dsc/downstairs-8820.txt (548227 bytes)
5472025-10-15T16:09:13.550Zuploaded: /tmp/test_up-build/dsc/downstairs-8820.txt
5482025-10-15T16:09:13.553Zuploading: /tmp/test_up-build/dsc/downstairs-8830.txt (979734 bytes)
5492025-10-15T16:09:14.573Zuploaded: /tmp/test_up-build/dsc/downstairs-8830.txt
5502025-10-15T16:09:14.573Zuploading: /tmp/test_up-build/dsc/downstairs-8840.txt (543037 bytes)
5512025-10-15T16:09:15.591Zuploaded: /tmp/test_up-build/dsc/downstairs-8840.txt
5522025-10-15T16:09:15.595Zuploading: /tmp/debug/df.txt (1270 bytes)
5532025-10-15T16:09:16.602Zuploaded: /tmp/debug/df.txt
5542025-10-15T16:09:16.605Zuploading: /tmp/debug/dtrace.txt (718724 bytes)
5552025-10-15T16:09:17.623Zuploaded: /tmp/debug/dtrace.txt
5562025-10-15T16:09:17.627Zuploading: /tmp/debug/iostat.txt (219151 bytes)
5572025-10-15T16:09:17.635Zupload warning: file "/tmp/debug/iostat.txt" changed size mid upload: 219151 -> 221851
5582025-10-15T16:09:18.642Zuploaded: /tmp/debug/iostat.txt
5592025-10-15T16:09:18.645Zuploading: /tmp/debug/mpstat.txt (532189 bytes)
5602025-10-15T16:09:18.656Zupload warning: file "/tmp/debug/mpstat.txt" changed size mid upload: 532189 -> 539479
5612025-10-15T16:09:19.663Zuploaded: /tmp/debug/mpstat.txt
5622025-10-15T16:09:19.663Zuploading: /tmp/debug/paging.txt (95484 bytes)
5632025-10-15T16:09:19.673Zupload warning: file "/tmp/debug/paging.txt" changed size mid upload: 95484 -> 97065
5642025-10-15T16:09:20.680Zuploaded: /tmp/debug/paging.txt
5652025-10-15T16:09:20.680Zuploading: /tmp/debug/prstat.txt (1046371 bytes)
5662025-10-15T16:09:20.700Zupload warning: file "/tmp/debug/prstat.txt" changed size mid upload: 1046371 -> 1060568
5672025-10-15T16:09:21.708Zuploaded: /tmp/debug/prstat.txt
5682025-10-15T16:09:21.708Zuploading: /tmp/debug/psrinfo.txt (1528 bytes)
5692025-10-15T16:09:22.718Zuploaded: /tmp/debug/psrinfo.txt
5702025-10-15T16:09:22.722Zuploading: /tmp/debug/upstairs-info.txt (85323 bytes)
5712025-10-15T16:09:23.732Zuploaded: /tmp/debug/upstairs-info.txt