01K86WXEW8DT8XQ5703TQWXJ91: 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: 01K86WXY9Y90JW5CWCEXWW7STG

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-10-22T21:42:44.129Zjob dependencies complete; ready to run (waiting for 18 m 24 s)
22025-10-22T21:43:48.460Zjob assigned to worker 01K86XZV28DQGXGHZBGF5KVG0V [factory aws, i-015f2193fa6a3ec8a] (queued for 1 m 4 s)
32025-10-22T21:43:57.138Zdownloading input: /input/build/work/bins/crucible-downstairs.gz
42025-10-22T21:43:58.648Zdownloaded input: /input/build/work/bins/crucible-downstairs.gz
52025-10-22T21:43:58.648Zdownloading input: /input/build/work/bins/crucible-hammer.gz
62025-10-22T21:44:00.022Zdownloaded input: /input/build/work/bins/crucible-hammer.gz
72025-10-22T21:44:00.023Zdownloading input: /input/build/work/bins/crutest.gz
82025-10-22T21:44:01.693Zdownloaded input: /input/build/work/bins/crutest.gz
92025-10-22T21:44:01.693Zdownloading input: /input/build/work/bins/dsc.gz
102025-10-22T21:44:02.472Zdownloaded input: /input/build/work/bins/dsc.gz
112025-10-22T21:44:02.477Zdownloading input: /input/build/work/scripts/perf-downstairs-tick.d
122025-10-22T21:44:02.496Zdownloaded input: /input/build/work/scripts/perf-downstairs-tick.d
132025-10-22T21:44:02.496Zdownloading input: /input/build/work/scripts/test_ds.sh
142025-10-22T21:44:02.525Zdownloaded input: /input/build/work/scripts/test_ds.sh
152025-10-22T21:44:02.525Zdownloading input: /input/build/work/scripts/test_live_repair.sh
162025-10-22T21:44:02.551Zdownloaded input: /input/build/work/scripts/test_live_repair.sh
172025-10-22T21:44:02.551Zdownloading input: /input/build/work/scripts/test_repair.sh
182025-10-22T21:44:02.579Zdownloaded input: /input/build/work/scripts/test_repair.sh
192025-10-22T21:44:02.579Zdownloading input: /input/build/work/scripts/test_replay.sh
202025-10-22T21:44:02.610Zdownloaded input: /input/build/work/scripts/test_replay.sh
212025-10-22T21:44:02.611Zdownloading input: /input/build/work/scripts/test_up.sh
222025-10-22T21:44:02.639Zdownloaded input: /input/build/work/scripts/test_up.sh
232025-10-22T21:44:02.639Zdownloading input: /input/build/work/scripts/upstairs_info.d
242025-10-22T21:44:02.666Zdownloaded input: /input/build/work/scripts/upstairs_info.d
252025-10-22T21:44:02.672Zdownloading input: /input/build/tmp/cargo-test-out.log
262025-10-22T21:44:03.264Zdownloaded input: /input/build/tmp/cargo-test-out.log
 
272025-10-22T21:44:03.264Zstarting task 0: "setup"
282025-10-22T21:44:03.274Z++ uname -s
292025-10-22T21:44:03.274Z+ kern=SunOS
302025-10-22T21:44:03.274Z+ build_user=build
312025-10-22T21:44:03.278Z+ build_uid=12345
322025-10-22T21:44:03.278Z+ work_dir=/work
332025-10-22T21:44:03.278Z+ input_dir=/input
342025-10-22T21:44:03.278Z+ [[ 0 == 12345 ]]
352025-10-22T21:44:03.278Z+ case "$kern" in
362025-10-22T21:44:03.278Z+ groupadd -g 12345 build
372025-10-22T21:44:03.278Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
382025-10-22T21:44:05.262Z+ zfs create -o mountpoint=/work rpool/work
392025-10-22T21:44:05.609Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
402025-10-22T21:44:05.612Z+ home_fs=zfs
412025-10-22T21:44:05.613Z+ [[ zfs == autofs ]]
422025-10-22T21:44:05.613Z+ mkdir -p /home/build
432025-10-22T21:44:05.616Z+ chown build:build /home/build /work
442025-10-22T21:44:07.616Z+ chmod 0700 /home/build /work
452025-10-22T21:44:07.619Zprocess exited: duration 4377 ms, exit code 0
 
462025-10-22T21:44:07.626Zstarting task 1: "authentication"
472025-10-22T21:44:07.648Zprocess exited: duration 21 ms, exit code 0
 
482025-10-22T21:44:07.655Zstarting task 2: "build"
492025-10-22T21:44:07.660Z+ banner cores
502025-10-22T21:44:07.663Z
512025-10-22T21:44:07.663Z #### #### ##### ###### ####
522025-10-22T21:44:07.663Z # # # # # # # #
532025-10-22T21:44:07.663Z # # # # # ##### ####
542025-10-22T21:44:07.663Z # # # ##### # #
552025-10-22T21:44:07.663Z # # # # # # # # #
562025-10-22T21:44:07.663Z #### #### # # ###### ####
572025-10-22T21:44:07.664Z
582025-10-22T21:44:07.664Z+ pfexec coreadm -i /tmp/core.%f.%p -g /tmp/core.%f.%p -e global -e log -e proc-setid -e global-setid
592025-10-22T21:44:07.671Z+ echo 'input bins dir contains:'
602025-10-22T21:44:07.674Zinput bins dir contains:
612025-10-22T21:44:07.674Z+ ls -ltr /input/build/work/bins
622025-10-22T21:44:07.674Ztotal 944231
632025-10-22T21:44:07.674Z-rw-r--r-- 1 root root 141185826 Oct 22 21:43 crucible-downstairs.gz
642025-10-22T21:44:07.674Z-rw-r--r-- 1 root root 134081527 Oct 22 21:43 crucible-hammer.gz
652025-10-22T21:44:07.675Z-rw-r--r-- 1 root root 139138487 Oct 22 21:44 crutest.gz
662025-10-22T21:44:07.675Z-rw-r--r-- 1 root root 68719800 Oct 22 21:44 dsc.gz
672025-10-22T21:44:07.675Z+ banner unpack
682025-10-22T21:44:07.678Z
692025-10-22T21:44:07.678Z # # # # ##### ## #### # #
702025-10-22T21:44:07.678Z # # ## # # # # # # # # #
712025-10-22T21:44:07.678Z # # # # # # # # # # ####
722025-10-22T21:44:07.678Z # # # # # ##### ###### # # #
732025-10-22T21:44:07.678Z # # # ## # # # # # # #
742025-10-22T21:44:07.678Z #### # # # # # #### # #
752025-10-22T21:44:07.678Z
762025-10-22T21:44:07.678Z+ mkdir -p /var/tmp/bins
772025-10-22T21:44:07.682Z+ for t in "$input/bins/"*.gz
782025-10-22T21:44:07.682Z++ basename /input/build/work/bins/crucible-downstairs.gz
792025-10-22T21:44:07.682Z+ b=crucible-downstairs.gz
802025-10-22T21:44:07.682Z+ b=crucible-downstairs
812025-10-22T21:44:07.682Z+ gunzip
822025-10-22T21:44:10.598Z+ chmod +x /var/tmp/bins/crucible-downstairs
832025-10-22T21:44:10.602Z+ for t in "$input/bins/"*.gz
842025-10-22T21:44:10.605Z++ basename /input/build/work/bins/crucible-hammer.gz
852025-10-22T21:44:10.605Z+ b=crucible-hammer.gz
862025-10-22T21:44:10.605Z+ b=crucible-hammer
872025-10-22T21:44:10.605Z+ gunzip
882025-10-22T21:44:13.370Z+ chmod +x /var/tmp/bins/crucible-hammer
892025-10-22T21:44:13.374Z+ for t in "$input/bins/"*.gz
902025-10-22T21:44:13.377Z++ basename /input/build/work/bins/crutest.gz
912025-10-22T21:44:13.377Z+ b=crutest.gz
922025-10-22T21:44:13.377Z+ b=crutest
932025-10-22T21:44:13.377Z+ gunzip
942025-10-22T21:44:16.289Z+ chmod +x /var/tmp/bins/crutest
952025-10-22T21:44:16.292Z+ for t in "$input/bins/"*.gz
962025-10-22T21:44:16.293Z++ basename /input/build/work/bins/dsc.gz
972025-10-22T21:44:16.296Z+ b=dsc.gz
982025-10-22T21:44:16.296Z+ b=dsc
992025-10-22T21:44:16.296Z+ gunzip
1002025-10-22T21:44:17.687Z+ chmod +x /var/tmp/bins/dsc
1012025-10-22T21:44:17.692Z+ export BINDIR=/var/tmp/bins
1022025-10-22T21:44:17.692Z+ BINDIR=/var/tmp/bins
1032025-10-22T21:44:17.692Z+ export RUST_BACKTRACE=1
1042025-10-22T21:44:17.692Z+ RUST_BACKTRACE=1
1052025-10-22T21:44:17.692Z+ jobpid=1158
1062025-10-22T21:44:17.692Z+ echo 'Setup debug logging'
1072025-10-22T21:44:17.692ZSetup debug logging
1082025-10-22T21:44:17.692Z+ mkdir /tmp/debug
1092025-10-22T21:44:17.692Z+ sleep 3600
1102025-10-22T21:44:17.695Z+ psrinfo -v
1112025-10-22T21:44:17.698Z+ df -h
1122025-10-22T21:44:17.704Z+ prstat -d d -mLc 1
1132025-10-22T21:44:17.707Z+ iostat -T d -xn 1
1142025-10-22T21:44:17.707Z+ mpstat -T d 1
1152025-10-22T21:44:17.707Z+ vmstat -T d -p 1
1162025-10-22T21:44:17.707Z+ pfexec dtrace -Z -s /input/build/work/scripts/perf-downstairs-tick.d
1172025-10-22T21:44:17.711Z+ banner test_up_encrypted
1182025-10-22T21:44:17.711Z+ pfexec dtrace -Z -s /input/build/work/scripts/upstairs_info.d
1192025-10-22T21:44:17.711Z
1202025-10-22T21:44:17.711Z ##### ###### #### ##### # # ##### ###### # #
1212025-10-22T21:44:17.711Z # # # # # # # # # ## #
1222025-10-22T21:44:17.711Z # ##### #### # # # # # ##### # # #
1232025-10-22T21:44:17.711Z # # # # # # ##### # # # #
1242025-10-22T21:44:17.711Z # # # # # # # # # # ##
1252025-10-22T21:44:17.711Z # ###### #### # ####### #### # ####### ###### # #
1262025-10-22T21:44:17.711Z
1272025-10-22T21:44:17.711Z+ ptime -m bash /input/build/work/scripts/test_up.sh -N encrypted
1282025-10-22T21:44:17.721Z/input/build/work
1292025-10-22T21:44:17.747ZTurn off color for downstairs dump
1302025-10-22T21:44:17.773ZUpstairs using key: 7GnNSU+R0L2RxeIAzZMXpkARtfWhFa64ms7TEsjpI5k=
1312025-10-22T21:44:17.777Zdsc output goes to /tmp/test_up-build/dsc-out.txt
1322025-10-22T21:44:17.777ZCreating 3 downstairs regions
1332025-10-22T21:44:18.063ZStarting 3 downstairs
1342025-10-22T21:44:18.066Zdsc started at PID: 1204
1352025-10-22T21:44:23.243ZDisable automatic restart on all downstairs
1362025-10-22T21:44:23.296Z
1372025-10-22T21:44:23.296ZBegin tests, output goes to /tmp/test_up-build/test_up_out.txt
1382025-10-22T21:44:23.336ZRunning test: span
1392025-10-22T21:44:27.424ZCompleted test: span
1402025-10-22T21:44:32.432ZRunning test: big
1412025-10-22T21:44:36.750ZCompleted test: big
1422025-10-22T21:44:41.758ZRunning test: dep
1432025-10-22T21:45:34.510ZCompleted test: dep
1442025-10-22T21:45:39.518ZRunning test: balloon
1452025-10-22T21:46:20.684ZCompleted test: balloon
1462025-10-22T21:46:25.692ZRunning test: deactivate
1472025-10-22T21:46:30.342ZCompleted test: deactivate
1482025-10-22T21:46:35.350ZRunning hammer
1492025-10-22T21:46:48.336ZRun repair tests
1502025-10-22T21:46:48.340Z/var/tmp/bins/crutest fill -g 31 -q --key 7GnNSU+R0L2RxeIAzZMXpkARtfWhFa64ms7TEsjpI5k= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file
1512025-10-22T21:46:48.399Z{"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-22T21:46:47.624518365Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"task":"crutest"}
1522025-10-22T21:46:48.402Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.625130533Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"task":"crutest"}
1532025-10-22T21:46:48.403Z{"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-22T21:46:47.62711548Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"task":"crutest"}
1542025-10-22T21:46:48.403Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.627296989Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241}
1552025-10-22T21:46:48.403Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"9063dde9565406ad9efc6e457bbffa920b2c2351\",\n git_commit_timestamp: \"2025-10-22T21:23:18.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-22T21:46:47.627346624Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241}
1562025-10-22T21:46:48.403Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.627370961Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241}
1572025-10-22T21:46:48.403Z{"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-22T21:46:47.627393758Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241}
1582025-10-22T21:46:48.403Z{"msg":"Crucible b8c454ff-907b-4550-bdd5-f54cdd8afe96 has session id: 6bfd4f23-fd1b-4924-afac-811e94f66c67","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.627950493Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1592025-10-22T21:46:48.403Z{"msg":"Upstairs opts: Upstairs UUID: b8c454ff-907b-4550-bdd5-f54cdd8afe96, 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-22T21:46:47.627998417Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1602025-10-22T21:46:48.403Z{"msg":"Crucible stats registered with UUID: b8c454ff-907b-4550-bdd5-f54cdd8afe96","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.628018505Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1612025-10-22T21:46:48.403Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-10-22T21:46:47.628035293Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1622025-10-22T21:46:48.403Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.628233869Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"io task","client":"1","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1632025-10-22T21:46:48.403Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.628284353Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"io task","client":"2","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1642025-10-22T21:46:48.403Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.628305301Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"io task","client":"0","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1652025-10-22T21:46:48.407Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.628893422Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"task":"crutest"}
1662025-10-22T21:46:48.408Z{"msg":"The guest has requested activation with gen:31","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.628938437Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241}
1672025-10-22T21:46:48.408Z{"msg":"b8c454ff-907b-4550-bdd5-f54cdd8afe96 active request set","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.629044184Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1682025-10-22T21:46:48.408Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.629073561Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"client":"0","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1692025-10-22T21:46:48.408Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.629092548Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"client":"1","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1702025-10-22T21:46:48.408Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.629210165Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"client":"2","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1712025-10-22T21:46:48.408Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.62925068Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"io task","client":"2","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1722025-10-22T21:46:48.408Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.629290625Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"io task","client":"0","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1732025-10-22T21:46:48.408Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.629322032Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"io task","client":"1","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1742025-10-22T21:46:48.408Z{"msg":"ds_connection connected from Ok(127.0.0.1:48138)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.629349358Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"io task","client":"2","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1752025-10-22T21:46:48.408Z{"msg":"ds_connection connected from Ok(127.0.0.1:44614)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.629377055Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"io task","client":"0","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1762025-10-22T21:46:48.408Z{"msg":"ds_connection connected from Ok(127.0.0.1:52639)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.629650293Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"io task","client":"1","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1772025-10-22T21:46:48.408Z{"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-22T21:46:47.630436241Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"client":"0","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1782025-10-22T21:46:48.408Z{"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-22T21:46:47.630489624Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"client":"2","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1792025-10-22T21:46:48.408Z{"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-22T21:46:47.630537109Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"client":"1","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1802025-10-22T21:46:48.408Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.630886098Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1812025-10-22T21:46:48.408Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.630927273Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1822025-10-22T21:46:48.408Z{"msg":"[0]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.63095669Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1832025-10-22T21:46:48.408Z{"msg":"[0]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.630993565Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1842025-10-22T21:46:48.408Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631031841Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1852025-10-22T21:46:48.408Z{"msg":"[1]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631061028Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1862025-10-22T21:46:48.408Z{"msg":"[1]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631092654Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1872025-10-22T21:46:48.408Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631132789Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"Wait for a query_work_queue command to finish before sending IO
1882025-10-22T21:46:48.408Z6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1892025-10-22T21:46:48.408Z{"msg":"[2]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631183533Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1902025-10-22T21:46:48.408Z{"msg":"[2]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631222318Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1912025-10-22T21:46:48.408Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631260504Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1922025-10-22T21:46:48.408Z{"msg":"Max found gen is 26","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.63129592Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1932025-10-22T21:46:48.408Z{"msg":"Generation requested: 31 >= found:26","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631319307Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1942025-10-22T21:46:48.408Z{"msg":"Next flush: 1500","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631343814Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1952025-10-22T21:46:48.408Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631360882Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"":"downstairs","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1962025-10-22T21:46:48.408Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631395608Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1972025-10-22T21:46:48.408Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631417416Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"client":"0","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1982025-10-22T21:46:48.409Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631447022Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"client":"1","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
1992025-10-22T21:46:48.409Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.63146504Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"client":"2","":"downstairs","session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
2002025-10-22T21:46:48.409Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631482958Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
2012025-10-22T21:46:48.409Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631506085Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
2022025-10-22T21:46:48.409Z{"msg":"b8c454ff-907b-4550-bdd5-f54cdd8afe96 is now active with session: 6bfd4f23-fd1b-4924-afac-811e94f66c67","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631535682Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
2032025-10-22T21:46:48.409Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2042025-10-22T21:46:48.409Z30,"time":"2025-10-22T21:46:47.631566928Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241,"session_id":"6bfd4f23-fd1b-4924-afac-811e94f66c67"}
2052025-10-22T21:46:48.409Z{"msg":"The guest has finished waiting for activation with:31","v":0,"nameFill test
2062025-10-22T21:46:48.409Z":"crucible","level":30,"time":"2025-10-22T21:46:47.631596665Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241}
2072025-10-22T21:46:48.409Z{"msg":"Activated sub_volume b8c454ff-907b-4550-bdd5-f54cdd8afe96","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:47.631611633Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1241}
2082025-10-22T21:46:48.446ZRead and Verify all blocks (0..50 range:false)
2092025-10-22T21:46:48.498ZWrote out file "/var/tmp/test_up-build/verify_file"
2102025-10-22T21:46:48.498ZCLIENT: Tests done. All submitted work has been ACK'd
2112025-10-22T21:46:48.501Z----------------------------------------------------------------
2122025-10-22T21:46:48.501Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:1
2132025-10-22T21:46:48.501ZStates: Active Active Active
2142025-10-22T21:46:48.501ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2152025-10-22T21:46:48.501Z 1002 Acked Read 50 Done Done Done false
2162025-10-22T21:46:48.501Z STATES DS:0 DS:1 DS:2 TOTAL
2172025-10-22T21:46:48.501Z Sent 0 0 0 0
2182025-10-22T21:46:48.501Z Done 1 1 1 3
2192025-10-22T21:46:48.501Z Skipped 0 0 0 0
2202025-10-22T21:46:48.501Z Error 0 0 0 0
2212025-10-22T21:46:48.501ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
2222025-10-22T21:46:48.501ZDownstairs last five completed: 1001 1000
2232025-10-22T21:46:48.501ZUpstairs last five completed: 1002 1001 1000
2242025-10-22T21:46:48.501ZCLIENT: Up:0 ds:1 act:3
2252025-10-22T21:46:52.500Z----------------------------------------------------------------
2262025-10-22T21:46:52.500Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:0
2272025-10-22T21:46:52.500ZDownstairs last five completed: 1003 1002 1001 1000
2282025-10-22T21:46:52.500ZUpstairs last five completed: 1003 1002 1001 1000
2292025-10-22T21:46:52.500ZCLIENT: Up:0 ds:0 act:3
2302025-10-22T21:46:52.500ZCLIENT: All crucible jobs finished, exiting program
2312025-10-22T21:46:52.512ZRepair setup passed
2322025-10-22T21:46:52.516ZCopy the region for /var/tmp/test_up-build/8830
2332025-10-22T21:46:52.523Zcp -r /var/tmp/test_up-build/8830 /var/tmp/test_up-build/previous
2342025-10-22T21:46:52.523Z/var/tmp/bins/crutest fill -g 32 -q --key 7GnNSU+R0L2RxeIAzZMXpkARtfWhFa64ms7TEsjpI5k= --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-22T21:46:52.580Z{"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-22T21:46:51.805350161Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"task":"crutest"}
2362025-10-22T21:46:52.584Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.805963609Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"task":"crutest"}
2372025-10-22T21:46:52.584Z{"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-22T21:46:51.80783577Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"task":"crutest"}
2382025-10-22T21:46:52.584Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.808066223Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247}
2392025-10-22T21:46:52.584Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"9063dde9565406ad9efc6e457bbffa920b2c2351\",\n git_commit_timestamp: \"2025-10-22T21:23:18.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-22T21:46:51.808153482Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247}
2402025-10-22T21:46:52.584Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.808200377Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247}
2412025-10-22T21:46:52.584Z{"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-22T21:46:51.808245522Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247}
2422025-10-22T21:46:52.584Z{"msg":"Crucible ef297aa5-8c91-485b-863a-2ecc62516406 has session id: 09058353-1a1c-4869-9a9b-a118d6159ece","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.808783718Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2432025-10-22T21:46:52.584Z{"msg":"Upstairs opts: Upstairs UUID: ef297aa5-8c91-485b-863a-2ecc62516406, 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-22T21:46:51.808850251Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2442025-10-22T21:46:52.584Z{"msg":"Crucible stats registered with UUID: ef297aa5-8c91-485b-863a-2ecc62516406","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.808892535Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2452025-10-22T21:46:52.584Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-10-22T21:46:51.808930321Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2462025-10-22T21:46:52.584Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.809093502Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"io task","client":"1","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2472025-10-22T21:46:52.589Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.809171463Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"io task","client":"0","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2482025-10-22T21:46:52.589Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.809212778Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"io task","client":"2","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2492025-10-22T21:46:52.589Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.80996038Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"task":"crutest"}
2502025-10-22T21:46:52.589Z{"msg":"The guest has requested activation with gen:32","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.810014184Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247}
2512025-10-22T21:46:52.589Z{"msg":"ef297aa5-8c91-485b-863a-2ecc62516406 active request set","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.810102973Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2522025-10-22T21:46:52.589Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.8101364Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"client":"0","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2532025-10-22T21:46:52.589Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.810155647Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"client":"1","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2542025-10-22T21:46:52.589Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.810201592Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"client":"2","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2552025-10-22T21:46:52.589Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.810233718Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"io task","client":"2","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2562025-10-22T21:46:52.589Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.810259785Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"io task","client":"0","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2572025-10-22T21:46:52.589Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.81030369Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"io task","client":"1","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2582025-10-22T21:46:52.589Z{"msg":"ds_connection connected from Ok(127.0.0.1:43338)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.810332177Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"io task","client":"1","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2592025-10-22T21:46:52.589Z{"msg":"ds_connection connected from Ok(127.0.0.1:42443)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.810367182Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"io task","client":"2","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2602025-10-22T21:46:52.589Z{"msg":"ds_connection connected from Ok(127.0.0.1:44101)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.810576988Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"io task","client":"0","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2612025-10-22T21:46:52.589Z{"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-22T21:46:51.811760909Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"client":"1","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2622025-10-22T21:46:52.589Z{"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-22T21:46:51.811881215Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"client":"0","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2632025-10-22T21:46:52.589Z{"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-22T21:46:51.812039996Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"client":"2","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2642025-10-22T21:46:52.589Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812146574Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2652025-10-22T21:46:52.589Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812205617Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2662025-10-22T21:46:52.589Z{"msg":"[0]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812356079Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2672025-10-22T21:46:52.589Z{"msg":"[0]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812391325Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2682025-10-22T21:46:52.589Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812421711Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2692025-10-22T21:46:52.589Z{"msg":"[1]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812458667Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2702025-10-22T21:46:52.589Z{"msg":"[1]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812496313Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2712025-10-22T21:46:52.589Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO
2722025-10-22T21:46:52.589Z,"time":"2025-10-22T21:46:51.812534488Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2732025-10-22T21:46:52.589Z{"msg":"[2]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812573314Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2742025-10-22T21:46:52.589Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812609949Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2752025-10-22T21:46:52.589Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812647105Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2762025-10-22T21:46:52.589Z{"msg":"Max found gen is 32","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812682391Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2772025-10-22T21:46:52.589Z{"msg":"Generation requested: 32 >= found:32"Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2782025-10-22T21:46:52.590Z,"v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812724086Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2792025-10-22T21:46:52.590Z{"msg":"Next flush: 1501","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812755042Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2802025-10-22T21:46:52.590Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812791698Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"":"downstairs","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2812025-10-22T21:46:52.590Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812829113Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2822025-10-22T21:46:52.590Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"Loading write count information from file "/var/tmp/test_up-build/verify_file"
2832025-10-22T21:46:52.590Zcrucible","level":30,"time":"2025-10-22T21:46:51.812869369Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"client":"0","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2842025-10-22T21:46:52.590Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30Fill test
2852025-10-22T21:46:52.590Z,"time":"2025-10-22T21:46:51.812906235Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"client":"1","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2862025-10-22T21:46:52.590Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812935971Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"client":"2","":"downstairs","session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2872025-10-22T21:46:52.590Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812968707Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2882025-10-22T21:46:52.590Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.812996914Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2892025-10-22T21:46:52.590Z{"msg":"ef297aa5-8c91-485b-863a-2ecc62516406 is now active with session: 09058353-1a1c-4869-9a9b-a118d6159ece","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.81302777Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2902025-10-22T21:46:52.590Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.813057417Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247,"session_id":"09058353-1a1c-4869-9a9b-a118d6159ece"}
2912025-10-22T21:46:52.590Z{"msg":"The guest has finished waiting for activation with:32","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.813084963Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247}
2922025-10-22T21:46:52.590Z{"msg":"Activated sub_volume ef297aa5-8c91-485b-863a-2ecc62516406","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:51.8131147Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247}
2932025-10-22T21:46:52.627ZRead and Verify all blocks (0..50 range:false)
2942025-10-22T21:46:52.667ZWrote out file "/var/tmp/test_up-build/verify_file"
2952025-10-22T21:46:52.667ZCLIENT: Tests done. All submitted work has been ACK'd
2962025-10-22T21:46:52.671Z----------------------------------------------------------------
2972025-10-22T21:46:52.671Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:1
2982025-10-22T21:46:52.671ZStates: Active Active Active
2992025-10-22T21:46:52.671ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
3002025-10-22T21:46:52.671Z 1002 Acked Read 50 Done Done Done false
3012025-10-22T21:46:52.671Z STATES DS:0 DS:1 DS:2 TOTAL
3022025-10-22T21:46:52.671Z Sent 0 0 0 0
3032025-10-22T21:46:52.671Z Done 1 1 1 3
3042025-10-22T21:46:52.671Z Skipped 0 0 0 0
3052025-10-22T21:46:52.671Z Error 0 0 0 0
3062025-10-22T21:46:52.671ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
3072025-10-22T21:46:52.671ZDownstairs last five completed: 1001 1000
3082025-10-22T21:46:52.671ZUpstairs last five completed: 1002 1001 1000
3092025-10-22T21:46:52.671ZCLIENT: Up:0 ds:1 act:3
3102025-10-22T21:46:56.669Z----------------------------------------------------------------
3112025-10-22T21:46:56.669Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:0
3122025-10-22T21:46:56.669ZDownstairs last five completed: 1003 1002 1001 1000
3132025-10-22T21:46:56.669ZUpstairs last five completed: 1003 1002 1001 1000
3142025-10-22T21:46:56.669ZCLIENT: Up:0 ds:0 act:3
3152025-10-22T21:46:56.669ZCLIENT: All crucible jobs finished, exiting program
3162025-10-22T21:46:56.672Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-10-22T21:46:55.89344884Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1247}
3172025-10-22T21:46:56.676ZRepair part 1 passed
3182025-10-22T21:46:56.676Z
3192025-10-22T21:46:56.676ZKill the current downstairs
3202025-10-22T21:46:56.848ZDownstairs 2 stopped
3212025-10-22T21:46:56.849Zmv /var/tmp/test_up-build/8830 /var/tmp/test_up-build/new
3222025-10-22T21:46:56.852ZNow put back the original so we have a mismatch
3232025-10-22T21:46:56.852Zmv /var/tmp/test_up-build/previous /var/tmp/test_up-build/8830
3242025-10-22T21:46:56.855ZRestart downstairs with old directory
3252025-10-22T21:46:56.907Z/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-22T21:46:56.927ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
3272025-10-22T21:46:56.930Z 0 000-009 32 32 31 1501 1501 1500 F F F <---
3282025-10-22T21:46:56.930Z 1 010-019 32 32 31 1501 1501 1500 F F F <---
3292025-10-22T21:46:56.930Z 2 020-029 32 32 31 1501 1501 1500 F F F <---
3302025-10-22T21:46:56.930Z 3 030-039 32 32 31 1501 1501 1500 F F F <---
3312025-10-22T21:46:56.930Z 4 040-049 32 32 31 1501 1501 1500 F F F <---
3322025-10-22T21:46:56.930ZMax gen: 32, Max flush: 1501
3332025-10-22T21:46:57.187ZError: Difference in extent metadata found!
3342025-10-22T21:46:57.187Z
3352025-10-22T21:46:57.187ZStack backtrace:
3362025-10-22T21:46:57.187Z 0: anyhow::error::<impl anyhow::Error>::msg
3372025-10-22T21:46:57.187Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/backtrace.rs:27:14
3382025-10-22T21:46:57.187Z 1: anyhow::__private::format_err
3392025-10-22T21:46:57.187Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/lib.rs:695:13
3402025-10-22T21:46:57.208Zdump test found error as expected
3412025-10-22T21:46:57.211Z
3422025-10-22T21:46:57.211Z
3432025-10-22T21:46:57.211Z/var/tmp/bins/crutest verify --range -g 33 -q --key 7GnNSU+R0L2RxeIAzZMXpkARtfWhFa64ms7TEsjpI5k= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
3442025-10-22T21:46:57.266Z{"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-22T21:46:56.4906026Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"task":"crutest"}
3452025-10-22T21:46:57.270Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.49119716Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"task":"crutest"}
3462025-10-22T21:46:57.270Z{"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-22T21:46:56.493065701Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"task":"crutest"}
3472025-10-22T21:46:57.270Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.493259998Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255}
3482025-10-22T21:46:57.270Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"9063dde9565406ad9efc6e457bbffa920b2c2351\",\n git_commit_timestamp: \"2025-10-22T21:23:18.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-22T21:46:56.493308342Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255}
3492025-10-22T21:46:57.270Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.49333156Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255}
3502025-10-22T21:46:57.270Z{"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-22T21:46:56.493354077Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255}
3512025-10-22T21:46:57.270Z{"msg":"Crucible 465852e7-7d0b-4011-be69-080917521c4c has session id: f91a22fb-c8e5-471a-b29d-1f1116002c8b","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.49401278Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3522025-10-22T21:46:57.270Z{"msg":"Upstairs opts: Upstairs UUID: 465852e7-7d0b-4011-be69-080917521c4c, 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-22T21:46:56.494122337Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3532025-10-22T21:46:57.270Z{"msg":"Crucible stats registered with UUID: 465852e7-7d0b-4011-be69-080917521c4c","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.494172451Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3542025-10-22T21:46:57.270Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-10-22T21:46:56.494218855Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3552025-10-22T21:46:57.270Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.49426191Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"1","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3562025-10-22T21:46:57.270Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.494319714Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"0","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3572025-10-22T21:46:57.270Z{"msg":"client is waiting for oneshot","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.494367618Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3582025-10-22T21:46:57.274Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.494987105Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"task":"crutest"}
3592025-10-22T21:46:57.274Z{"msg":"The guest has requested activation with gen:33","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495038119Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255}
3602025-10-22T21:46:57.274Z{"msg":"465852e7-7d0b-4011-be69-080917521c4c active request set","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495089613Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3612025-10-22T21:46:57.274Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495131748Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"0","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3622025-10-22T21:46:57.274Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495171764Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"1","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3632025-10-22T21:46:57.274Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495191761Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3642025-10-22T21:46:57.274Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495224197Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3652025-10-22T21:46:57.274Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495259823Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"0","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3662025-10-22T21:46:57.274Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495296059Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"1","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3672025-10-22T21:46:57.274Z{"msg":"ds_connection connected from Ok(127.0.0.1:47924)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495334535Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"0","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3682025-10-22T21:46:57.274Z{"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-22T21:46:56.495387028Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3692025-10-22T21:46:57.274Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2025-10-22T21:46:56.495421254Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3702025-10-22T21:46:57.274Z{"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-22T21:46:56.495466989Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3712025-10-22T21:46:57.274Z{"msg":"ds_connection connected from Ok(127.0.0.1:46178)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495507384Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"1","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3722025-10-22T21:46:57.274Z{"msg":"sleeping for 10s before connecting","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495592424Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3732025-10-22T21:46:57.274Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.495637519Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3742025-10-22T21:46:57.274Z{"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-22T21:46:56.496497468Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"0","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3752025-10-22T21:46:57.274Z{"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-22T21:46:56.496594987Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"1","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3762025-10-22T21:46:57.274Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.496828919Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3772025-10-22T21:46:57.274Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:46:56.496876874Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3782025-10-22T21:47:07.273Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.496687596Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3792025-10-22T21:47:07.280Z{"msg":"ds_connection connected from Ok(127.0.0.1:44945)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.496859906Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"io task","client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3802025-10-22T21:47:07.280Z{"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-22T21:47:06.498262661Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3812025-10-22T21:47:07.280Z{"msg":"[0]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.49869454Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3822025-10-22T21:47:07.280Z{"msg":"[0]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498732496Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3832025-10-22T21:47:07.280Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498753474Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3842025-10-22T21:47:07.280Z{"msg":"[1]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.49878076Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3852025-10-22T21:47:07.280Z{"msg":"[1]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498798858Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3862025-10-22T21:47:07.280Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498823265Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3872025-10-22T21:47:07.280Z{"msg":"[2]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498841243Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3882025-10-22T21:47:07.280Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498864641Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3892025-10-22T21:47:07.280Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498882798Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3902025-10-22T21:47:07.280Z{"msg":"Max found gen is 33","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498905526Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3912025-10-22T21:47:07.280Z{"msg":"Generation requested: 33 >= found:33","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498923234Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3922025-10-22T21:47:07.280Z{"msg":"Next flush: 1502","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498946041Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3932025-10-22T21:47:07.280Z{"msg":"extent 0 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.498971688Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3942025-10-22T21:47:07.280Z{"msg":"extent:0 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499017012Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3952025-10-22T21:47:07.280Z{"msg":"found dest for source 0 for extent at index 0 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499045119Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3962025-10-22T21:47:07.280Z{"msg":"extent 1 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499071546Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3972025-10-22T21:47:07.280Z{"msg":"extent:1 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499102802Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3982025-10-22T21:47:07.281Z{"msg":"found dest for source 0 for extent at index 1 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.4991222Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
3992025-10-22T21:47:07.281Z{"msg":"extent 2 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499154067Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4002025-10-22T21:47:07.281Z{"msg":"extent:2 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499179504Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4012025-10-22T21:47:07.281Z{"msg":"found dest for source 0 for extent at index 2 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499205141Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4022025-10-22T21:47:07.281Z{"msg":"extent 3 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499231218Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4032025-10-22T21:47:07.281Z{"msg":"extent:3 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499262414Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4042025-10-22T21:47:07.281Z{"msg":"found dest for source 0 for extent at index 3 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499287161Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4052025-10-22T21:47:07.281Z{"msg":"extent 4 needs reconciliation: ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })]))","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499320997Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4062025-10-22T21:47:07.281Z{"msg":"extent:4 ClientMap(ClientData([Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 32, flush: 1501, dirty: false }), Some(ExtentMetadata { gen: 31, flush: 1500, dirty: false })])) => 0","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499363962Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4072025-10-22T21:47:07.281Z{"msg":"found dest for source 0 for extent at index 4 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499390989Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"mend","":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4082025-10-22T21:47:07.281Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499418785Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"0","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4092025-10-22T21:47:07.281Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499446502Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"1","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4102025-10-22T21:47:07.281Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499471529Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4112025-10-22T21:47:07.281Z{"msg":"Full repair list: {ExtentId(1): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(2): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(3): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(0): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(4): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }}","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499502955Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4122025-10-22T21:47:07.281Z{"msg":"Task list: [ReconcileIO { id: ReconciliationId(0), op: ExtentFlush { repair_id: ReconciliationId(0), extent_id: ExtentId(1), client_id: ClientId(0), flush_number: 1502, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(1), op: ExtentClose { repair_id: ReconciliationId(1), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(2), op: ExtentRepair { repair_id: ReconciliationId(2), 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(3), op: ExtentReopen { repair_id: ReconciliationId(3), extent_id: ExtentId(1) }, 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: 1502, 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(3), client_id: ClientId(0), flush_number: 1502, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(9), op: ExtentClose { repair_id: ReconciliationId(9), extent_id: ExtentId(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(0), client_id: ClientId(0), flush_number: 1502, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(13), op: ExtentClose { repair_id: ReconciliationId(13), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(14), op: ExtentRepair { repair_id: ReconciliationId(14), 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(15), op: ExtentReopen { repair_id: ReconciliationId(15), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(16), op: ExtentFlush { repair_id: ReconciliationId(16), extent_id: ExtentId(4), client_id: ClientId(0), flush_number: 1502, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(17), op: ExtentClose { repair_id: ReconciliationId(17), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(18), op: ExtentRepair { repair_id: ReconciliationId(18), 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(19), op: ExtentReopen { repair_id: ReconciliationId(19), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }]","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499708691Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4132025-10-22T21:47:07.281Z{"msg":"starting reconciliation 8c4b69e5-69bf-49fc-8b92-343be162e954: found 20 extents that need repair","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499736428Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4142025-10-22T21:47:07.281Z{"msg":"sending reconcile request ReconciliationId(2)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.499942974Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4152025-10-22T21:47:07.291Z{"msg":"sending reconcile request ReconciliationId(6)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.513983176Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4162025-10-22T21:47:07.294Z{"msg":"sending reconcile request ReconciliationId(10)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.517773891Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4172025-10-22T21:47:07.301Z{"msg":"sending reconcile request ReconciliationId(14)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.521509693Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4182025-10-22T21:47:07.304Z{"msg":"sending reconcile request ReconciliationId(18)","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.525429143Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4192025-10-22T21:47:07.308Z{"msg":"done with reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.528903265Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"":"downstairs","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4202025-10-22T21:47:07.308Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.528943731Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"0","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4212025-10-22T21:47:07.308Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.528963668Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"1","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4222025-10-22T21:47:07.308Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.528980816Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"client":"2","":"downstairs","session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4232025-10-22T21:47:07.308Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.529018512Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4242025-10-22T21:47:07.308Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.529037069Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4252025-10-22T21:47:07.308Z{"msg":"465852e7-7d0b-4011-be69-080917521c4c is now active with session: f91a22fb-c8e5-471a-b29d-1f1116002c8b","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.529055227Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255,"session_id":"f91a22fb-c8e5-471a-b29d-1f1116002c8b"}
4262025-10-22T21:47:07.308Z{"msg":"The guest has finished waiting for activation with:33","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO
4272025-10-22T21:47:07.308Z,"time":"2025-10-22T21:47:06.529078784Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255}
4282025-10-22T21:47:07.308Z{"msg":"Activated sub_volume 465852e7-7d0b-4011-be69-080917521c4c","v":0,"name":"crucible","level":30,"time":"2025-10-22T21:47:06.529100542Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255}
4292025-10-22T21:47:07.308ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
4302025-10-22T21:47:07.308ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
4312025-10-22T21:47:07.308ZRead and Verify all blocks (0..50 range:true)
4322025-10-22T21:47:07.346ZWrote out file "/var/tmp/test_up-build/verify_file"
4332025-10-22T21:47:07.346ZVerify test completed
4342025-10-22T21:47:07.350ZWrote out file "/var/tmp/test_up-build/verify_file"
4352025-10-22T21:47:07.350ZCLIENT: Tests done. All submitted work has been ACK'd
4362025-10-22T21:47:07.350Z----------------------------------------------------------------
4372025-10-22T21:47:07.350Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:1
4382025-10-22T21:47:07.350ZStates: Active Active Active
4392025-10-22T21:47:07.350ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
4402025-10-22T21:47:07.350Z 1000 Acked Read 50 Done Done Done false
4412025-10-22T21:47:07.350Z STATES DS:0 DS:1 DS:2 TOTAL
4422025-10-22T21:47:07.350Z Sent 0 0 0 0
4432025-10-22T21:47:07.350Z Done 1 1 1 3
4442025-10-22T21:47:07.350Z Skipped 0 0 0 0
4452025-10-22T21:47:07.350Z Error 0 0 0 0
4462025-10-22T21:47:07.350ZLast Flush: None None None
4472025-10-22T21:47:07.350ZDownstairs last five completed:
4482025-10-22T21:47:07.350ZUpstairs last five completed: 1000
4492025-10-22T21:47:07.350ZCLIENT: Up:0 ds:1 act:3
4502025-10-22T21:47:11.349Z----------------------------------------------------------------
4512025-10-22T21:47:11.349Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:0
4522025-10-22T21:47:11.349ZDownstairs last five completed: 1001 1000
4532025-10-22T21:47:11.349ZUpstairs last five completed: 1001 1000
4542025-10-22T21:47:11.349ZCLIENT: Up:0 ds:0 act:3
4552025-10-22T21:47:11.349ZCLIENT: All crucible jobs finished, exiting program
4562025-10-22T21:47:11.353Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-10-22T21:47:10.572149199Z","hostname":"w-01K86XZV28DQGXGHZBGF5KVG0V","pid":1255}
4572025-10-22T21:47:11.356ZRepair part 2 passed
4582025-10-22T21:47:11.356Z/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
4592025-10-22T21:47:11.377ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
4602025-10-22T21:47:11.380Z 0 000-009 32 32 32 1501 1501 1501 F F F
4612025-10-22T21:47:11.380Z 1 010-019 32 32 32 1501 1501 1501 F F F
4622025-10-22T21:47:11.380Z 2 020-029 32 32 32 1501 1501 1501 F F F
4632025-10-22T21:47:11.380Z 3 030-039 32 32 32 1501 1501 1501 F F F
4642025-10-22T21:47:11.380Z 4 040-049 32 32 32 1501 1501 1501 F F F
4652025-10-22T21:47:11.380ZMax gen: 32, Max flush: 1501
4662025-10-22T21:47:11.383Zdump test passed
4672025-10-22T21:47:11.383Z/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
4682025-10-22T21:47:11.400Z Extent 1
4692025-10-22T21:47:11.403ZGEN 32 32 32
4702025-10-22T21:47:11.403ZFLUSH_ID 1501 1501 1501
4712025-10-22T21:47:11.403ZDIRTY
4722025-10-22T21:47:11.403Z
4732025-10-22T21:47:11.404ZBLOCK D0 D1 D2 C0 C1 C2 DIFF
4742025-10-22T21:47:11.407Z010 A A A A A A
4752025-10-22T21:47:11.410Z011 A A A A A A
4762025-10-22T21:47:11.413Z012 A A A A A A
4772025-10-22T21:47:11.416Z013 A A A A A A
4782025-10-22T21:47:11.419Z014 A A A A A A
4792025-10-22T21:47:11.422Z015 A A A A A A
4802025-10-22T21:47:11.426Z016 A A A A A A
4812025-10-22T21:47:11.429Z017 A A A A A A
4822025-10-22T21:47:11.433Z018 A A A A A A
4832025-10-22T21:47:11.436Z019 A A A A A A
4842025-10-22T21:47:11.442Zdump extent test passed
4852025-10-22T21:47:11.445Z/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
4862025-10-22T21:47:11.461ZExtent 2 Block in extent 0 Actual block 20
4872025-10-22T21:47:11.464Z
4882025-10-22T21:47:11.467Z DATA SHA256 VER
4892025-10-22T21:47:11.467Z------ ---------------------------------------------------------------- ---
4902025-10-22T21:47:11.467Z 0 1d13af86361b6a921fe14788429acc0ec3378c0b30bf4d0def41253230b26620 A
4912025-10-22T21:47:11.467Z 1 1d13af86361b6a921fe14788429acc0ec3378c0b30bf4d0def41253230b26620 A
4922025-10-22T21:47:11.467Z 2 1d13af86361b6a921fe14788429acc0ec3378c0b30bf4d0def41253230b26620 A
4932025-10-22T21:47:11.467Z
4942025-10-22T21:47:11.467ZNONCES 0 1 2 DIFF
4952025-10-22T21:47:11.467Z------ ------------------------ ------------------------ ------------------------ -----
4962025-10-22T21:47:11.467Z 0 dc8cd1ca722f41a9ebde7cf7 dc8cd1ca722f41a9ebde7cf7 dc8cd1ca722f41a9ebde7cf7
4972025-10-22T21:47:11.467Z
4982025-10-22T21:47:11.467Z TAGS 0 1 2 DIFF
4992025-10-22T21:47:11.467Z------ -------------------------------- -------------------------------- -------------------------------- -----
5002025-10-22T21:47:11.467Z 0 1ff15740aecf126aea8d71072b19f196 1ff15740aecf126aea8d71072b19f196 1ff15740aecf126aea8d71072b19f196
5012025-10-22T21:47:11.468Z
5022025-10-22T21:47:11.468ZHASHES 0 1 2 DIFF
5032025-10-22T21:47:11.468Z------ ---------------- ---------------- ---------------- -----
5042025-10-22T21:47:11.468Z
5052025-10-22T21:47:11.471Zdump block test passed
5062025-10-22T21:47:11.471ZInitial upstairs tests have completed, stopping all downstairs
5072025-10-22T21:47:16.536ZCreating 4 larger downstairs regions
5082025-10-22T21:47:18.068ZStarting 4 downstairs
5092025-10-22T21:47:23.076Zdsc restarted at PID: 1268
5102025-10-22T21:47:23.301ZNow do the replace-reconcile test
5112025-10-22T21:47:23.357ZUsing 8840 for the replacement port
5122025-10-22T21:50:21.958ZCompleted test: replace-reconcile
5132025-10-22T21:50:21.961ZNow do the replace-before-active test
5142025-10-22T21:54:44.799ZCompleted test: replace-before-active
5152025-10-22T21:54:44.802ZAll tests have completed, stopping all downstairs
5162025-10-22T21:54:44.858Z
5172025-10-22T21:54:44.858ZAll Tests have passed
5182025-10-22T21:54:44.862Z10:28 Test duration
5192025-10-22T21:54:44.862Z
5202025-10-22T21:54:44.862Zreal 10:27.060565815
5212025-10-22T21:54:44.862Zuser 17:11.878772138
5222025-10-22T21:54:44.862Zsys 15.149897494
5232025-10-22T21:54:44.862Ztrap 0.559711194
5242025-10-22T21:54:44.862Ztflt 0.030244116
5252025-10-22T21:54:44.862Zdflt 0.037964307
5262025-10-22T21:54:44.862Zkflt 0.013012309
5272025-10-22T21:54:44.862Zlock 7:11:38.186369735
5282025-10-22T21:54:44.862Zslp 31:37.383554440
5292025-10-22T21:54:44.862Zlat 1:22.336869550
5302025-10-22T21:54:44.862Zstop 0.021526116
5312025-10-22T21:54:44.862Z+ echo 'test-up-encrypted ends'
5322025-10-22T21:54:44.862Ztest-up-encrypted ends
5332025-10-22T21:54:49.864Zprocess exited: duration 637118 ms, exit code 0
5342025-10-22T21:54:49.864Zexec warning: : stdio descriptors remain open after task exit; waiting 60 seconds for them to close
5352025-10-22T21:55:49.907Zexec warning: : stdout descriptor may be held open by a background process; giving up!
5362025-10-22T21:55:49.907Zexec warning: : stderr descriptor may be held open by a background process; giving up!
 
5372025-10-22T21:55:49.924Zfound 14 output files
5382025-10-22T21:55:49.924Zuploading: /tmp/test_up-build/dsc-out.txt (40311 bytes)
5392025-10-22T21:55:50.940Zuploaded: /tmp/test_up-build/dsc-out.txt
5402025-10-22T21:55:50.940Zuploading: /tmp/test_up-build/test_up_out.txt (14060269 bytes)
5412025-10-22T21:55:52.179Zuploaded: /tmp/test_up-build/test_up_out.txt
5422025-10-22T21:55:52.183Zuploading: /tmp/test_up-build/dsc/downstairs-8810.txt (2495 bytes)
5432025-10-22T21:55:53.192Zuploaded: /tmp/test_up-build/dsc/downstairs-8810.txt
5442025-10-22T21:55:53.193Zuploading: /tmp/test_up-build/dsc/downstairs-8820.txt (548238 bytes)
5452025-10-22T21:55:54.220Zuploaded: /tmp/test_up-build/dsc/downstairs-8820.txt
5462025-10-22T21:55:54.220Zuploading: /tmp/test_up-build/dsc/downstairs-8830.txt (979485 bytes)
5472025-10-22T21:55:55.256Zuploaded: /tmp/test_up-build/dsc/downstairs-8830.txt
5482025-10-22T21:55:55.259Zuploading: /tmp/test_up-build/dsc/downstairs-8840.txt (543001 bytes)
5492025-10-22T21:55:56.305Zuploaded: /tmp/test_up-build/dsc/downstairs-8840.txt
5502025-10-22T21:55:56.306Zuploading: /tmp/debug/df.txt (1270 bytes)
5512025-10-22T21:55:57.318Zuploaded: /tmp/debug/df.txt
5522025-10-22T21:55:57.318Zuploading: /tmp/debug/dtrace.txt (589340 bytes)
5532025-10-22T21:55:58.344Zuploaded: /tmp/debug/dtrace.txt
5542025-10-22T21:55:58.344Zuploading: /tmp/debug/iostat.txt (208038 bytes)
5552025-10-22T21:55:58.358Zupload warning: file "/tmp/debug/iostat.txt" changed size mid upload: 208038 -> 210438
5562025-10-22T21:55:59.365Zuploaded: /tmp/debug/iostat.txt
5572025-10-22T21:55:59.365Zuploading: /tmp/debug/mpstat.txt (505202 bytes)
5582025-10-22T21:55:59.384Zupload warning: file "/tmp/debug/mpstat.txt" changed size mid upload: 505202 -> 511763
5592025-10-22T21:56:00.411Zuploaded: /tmp/debug/mpstat.txt
5602025-10-22T21:56:00.411Zuploading: /tmp/debug/paging.txt (90755 bytes)
5612025-10-22T21:56:00.424Zupload warning: file "/tmp/debug/paging.txt" changed size mid upload: 90755 -> 92063
5622025-10-22T21:56:01.443Zuploaded: /tmp/debug/paging.txt
5632025-10-22T21:56:01.443Zuploading: /tmp/debug/prstat.txt (987719 bytes)
5642025-10-22T21:56:01.464Zupload warning: file "/tmp/debug/prstat.txt" changed size mid upload: 987719 -> 1003232
5652025-10-22T21:56:02.471Zuploaded: /tmp/debug/prstat.txt
5662025-10-22T21:56:02.471Zuploading: /tmp/debug/psrinfo.txt (1528 bytes)
5672025-10-22T21:56:03.482Zuploaded: /tmp/debug/psrinfo.txt
5682025-10-22T21:56:03.482Zuploading: /tmp/debug/upstairs-info.txt (78183 bytes)
5692025-10-22T21:56:04.498Zuploaded: /tmp/debug/upstairs-info.txt