01JJQDM3DDRV3436G4GDFSAGT0: test-up-unencrypted

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

Buildomat Job: 01JJQDMF9V71FFYX3MH9NXAXZQ

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-01-28T21:52:54.079Zjob dependencies complete; ready to run (waiting for 14 m 8 s)
22025-01-28T21:53:59.358Zjob assigned to worker 01JJQEEJV9J7Q4F56MKK1TGX8C [factory aws, i-0ceebf6f77a25b3bd] (queued for 1 m 5 s)
32025-01-28T21:54:07.265Zdownloading input: /input/build/work/bins/crucible-downstairs.gz
42025-01-28T21:54:08.557Zdownloaded input: /input/build/work/bins/crucible-downstairs.gz
52025-01-28T21:54:08.557Zdownloading input: /input/build/work/bins/crucible-hammer.gz
62025-01-28T21:54:09.674Zdownloaded input: /input/build/work/bins/crucible-hammer.gz
72025-01-28T21:54:09.674Zdownloading input: /input/build/work/bins/crutest.gz
82025-01-28T21:54:10.838Zdownloaded input: /input/build/work/bins/crutest.gz
92025-01-28T21:54:10.838Zdownloading input: /input/build/work/bins/dsc.gz
102025-01-28T21:54:11.507Zdownloaded input: /input/build/work/bins/dsc.gz
112025-01-28T21:54:11.510Zdownloading input: /input/build/work/scripts/perf-downstairs-tick.d
122025-01-28T21:54:11.528Zdownloaded input: /input/build/work/scripts/perf-downstairs-tick.d
132025-01-28T21:54:11.528Zdownloading input: /input/build/work/scripts/test_ds.sh
142025-01-28T21:54:11.544Zdownloaded input: /input/build/work/scripts/test_ds.sh
152025-01-28T21:54:11.545Zdownloading input: /input/build/work/scripts/test_live_repair.sh
162025-01-28T21:54:11.563Zdownloaded input: /input/build/work/scripts/test_live_repair.sh
172025-01-28T21:54:11.563Zdownloading input: /input/build/work/scripts/test_repair.sh
182025-01-28T21:54:11.580Zdownloaded input: /input/build/work/scripts/test_repair.sh
192025-01-28T21:54:11.580Zdownloading input: /input/build/work/scripts/test_replay.sh
202025-01-28T21:54:11.599Zdownloaded input: /input/build/work/scripts/test_replay.sh
212025-01-28T21:54:11.599Zdownloading input: /input/build/work/scripts/test_up.sh
222025-01-28T21:54:11.613Zdownloaded input: /input/build/work/scripts/test_up.sh
232025-01-28T21:54:11.613Zdownloading input: /input/build/work/scripts/upstairs_info.d
242025-01-28T21:54:11.633Zdownloaded input: /input/build/work/scripts/upstairs_info.d
252025-01-28T21:54:11.637Zdownloading input: /input/build/tmp/cargo-test-out.log
262025-01-28T21:54:12.292Zdownloaded input: /input/build/tmp/cargo-test-out.log
 
272025-01-28T21:54:12.293Zstarting task 0: "setup"
282025-01-28T21:54:12.305Z++ uname -s
292025-01-28T21:54:12.308Z+ kern=SunOS
302025-01-28T21:54:12.308Z+ case "$kern" in
312025-01-28T21:54:12.308Z+ groupadd -g 12345 build
322025-01-28T21:54:12.311Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
332025-01-28T21:54:14.318Z+ zfs create -o mountpoint=/work rpool/work
342025-01-28T21:54:14.487Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
352025-01-28T21:54:14.490Z+ home_fs=zfs
362025-01-28T21:54:14.490Z+ [[ zfs == autofs ]]
372025-01-28T21:54:14.490Z+ mkdir -p /home/build
382025-01-28T21:54:14.492Z+ chown build:build /home/build /work
392025-01-28T21:54:15.494Z+ chmod 0700 /home/build /work
402025-01-28T21:54:15.496Zprocess exited: duration 3203 ms, exit code 0
 
412025-01-28T21:54:15.502Zstarting task 1: "authentication"
422025-01-28T21:54:15.519Zprocess exited: duration 16 ms, exit code 0
 
432025-01-28T21:54:15.525Zstarting task 2: "build"
442025-01-28T21:54:15.530Z+ banner cores
452025-01-28T21:54:15.533Z
462025-01-28T21:54:15.533Z #### #### ##### ###### ####
472025-01-28T21:54:15.533Z # # # # # # # #
482025-01-28T21:54:15.533Z # # # # # ##### ####
492025-01-28T21:54:15.533Z # # # ##### # #
502025-01-28T21:54:15.533Z # # # # # # # # #
512025-01-28T21:54:15.533Z #### #### # # ###### ####
522025-01-28T21:54:15.533Z
532025-01-28T21:54:15.536Z+ pfexec coreadm -i /tmp/core.%f.%p -g /tmp/core.%f.%p -e global -e log -e proc-setid -e global-setid
542025-01-28T21:54:15.542Z+ echo 'input bins dir contains:'
552025-01-28T21:54:15.545Zinput bins dir contains:
562025-01-28T21:54:15.545Z+ ls -ltr /input/build/work/bins
572025-01-28T21:54:15.545Ztotal 787299
582025-01-28T21:54:15.545Z-rw-r--r-- 1 root root 116286027 Jan 28 21:54 crucible-downstairs.gz
592025-01-28T21:54:15.545Z-rw-r--r-- 1 root root 104477056 Jan 28 21:54 crucible-hammer.gz
602025-01-28T21:54:15.545Z-rw-r--r-- 1 root root 115710048 Jan 28 21:54 crutest.gz
612025-01-28T21:54:15.545Z-rw-r--r-- 1 root root 66364854 Jan 28 21:54 dsc.gz
622025-01-28T21:54:15.545Z+ banner unpack
632025-01-28T21:54:15.547Z
642025-01-28T21:54:15.547Z # # # # ##### ## #### # #
652025-01-28T21:54:15.548Z # # ## # # # # # # # # #
662025-01-28T21:54:15.548Z # # # # # # # # # # ####
672025-01-28T21:54:15.548Z # # # # # ##### ###### # # #
682025-01-28T21:54:15.548Z # # # ## # # # # # # #
692025-01-28T21:54:15.548Z #### # # # # # #### # #
702025-01-28T21:54:15.548Z
712025-01-28T21:54:15.548Z+ mkdir -p /var/tmp/bins
722025-01-28T21:54:15.551Z+ for t in "$input/bins/"*.gz
732025-01-28T21:54:15.551Z++ basename /input/build/work/bins/crucible-downstairs.gz
742025-01-28T21:54:15.553Z+ b=crucible-downstairs.gz
752025-01-28T21:54:15.553Z+ b=crucible-downstairs
762025-01-28T21:54:15.553Z+ gunzip
772025-01-28T21:54:17.967Z+ chmod +x /var/tmp/bins/crucible-downstairs
782025-01-28T21:54:17.970Z+ for t in "$input/bins/"*.gz
792025-01-28T21:54:17.973Z++ basename /input/build/work/bins/crucible-hammer.gz
802025-01-28T21:54:17.973Z+ b=crucible-hammer.gz
812025-01-28T21:54:17.973Z+ b=crucible-hammer
822025-01-28T21:54:17.973Z+ gunzip
832025-01-28T21:54:20.166Z+ chmod +x /var/tmp/bins/crucible-hammer
842025-01-28T21:54:20.169Z+ for t in "$input/bins/"*.gz
852025-01-28T21:54:20.172Z++ basename /input/build/work/bins/crutest.gz
862025-01-28T21:54:20.172Z+ b=crutest.gz
872025-01-28T21:54:20.172Z+ b=crutest
882025-01-28T21:54:20.172Z+ gunzip
892025-01-28T21:54:22.557Z+ chmod +x /var/tmp/bins/crutest
902025-01-28T21:54:22.560Z+ for t in "$input/bins/"*.gz
912025-01-28T21:54:22.562Z++ basename /input/build/work/bins/dsc.gz
922025-01-28T21:54:22.562Z+ b=dsc.gz
932025-01-28T21:54:22.563Z+ b=dsc
942025-01-28T21:54:22.563Z+ gunzip
952025-01-28T21:54:23.960Z+ chmod +x /var/tmp/bins/dsc
962025-01-28T21:54:23.962Z+ export BINDIR=/var/tmp/bins
972025-01-28T21:54:23.962Z+ BINDIR=/var/tmp/bins
982025-01-28T21:54:23.962Z+ export RUST_BACKTRACE=1
992025-01-28T21:54:23.962Z+ RUST_BACKTRACE=1
1002025-01-28T21:54:23.962Z+ jobpid=1144
1012025-01-28T21:54:23.965Z+ echo 'Setup debug logging'
1022025-01-28T21:54:23.965ZSetup debug logging
1032025-01-28T21:54:23.965Z+ mkdir /tmp/debug
1042025-01-28T21:54:23.965Z+ sleep 7200
1052025-01-28T21:54:23.966Z+ psrinfo -v
1062025-01-28T21:54:23.969Z+ df -h
1072025-01-28T21:54:23.976Z+ prstat -d d -mLc 1
1082025-01-28T21:54:23.979Z+ iostat -T d -xn 1
1092025-01-28T21:54:23.979Z+ mpstat -T d 1
1102025-01-28T21:54:23.979Z+ vmstat -T d -p 1
1112025-01-28T21:54:23.982Z+ pfexec dtrace -Z -s /input/build/work/scripts/perf-downstairs-tick.d
1122025-01-28T21:54:23.982Z+ banner test_up_unencrypted
1132025-01-28T21:54:23.982Z+ pfexec dtrace -Z -s /input/build/work/scripts/upstairs_info.d
1142025-01-28T21:54:23.985Z
1152025-01-28T21:54:23.985Z ##### ###### #### ##### # # ##### # # # #
1162025-01-28T21:54:23.985Z # # # # # # # # # # ## #
1172025-01-28T21:54:23.985Z # ##### #### # # # # # # # # # #
1182025-01-28T21:54:23.985Z # # # # # # ##### # # # # #
1192025-01-28T21:54:23.985Z # # # # # # # # # # # ##
1202025-01-28T21:54:23.985Z # ###### #### # ####### #### # ####### #### # #
1212025-01-28T21:54:23.985Z
1222025-01-28T21:54:23.985Z+ ptime -m bash /input/build/work/scripts/test_up.sh -N unencrypted
1232025-01-28T21:54:23.994Z/input/build/work
1242025-01-28T21:54:24.008ZTurn off color for downstairs dump
1252025-01-28T21:54:24.010Zdsc output goes to /tmp/test_up-build/dsc-out.txt
1262025-01-28T21:54:24.010ZCreating 3 downstairs regions
1272025-01-28T21:54:24.364ZStarting 3 downstairs
1282025-01-28T21:54:24.366Zdsc started at PID: 1189
1292025-01-28T21:54:29.544ZDisable automatic restart on all downstairs
1302025-01-28T21:54:29.599Z
1312025-01-28T21:54:29.599ZBegin tests, output goes to /tmp/test_up-build/test_up_out.txt
1322025-01-28T21:54:29.603ZRunning test: span
1332025-01-28T21:54:33.711ZCompleted test: span
1342025-01-28T21:54:38.718ZRunning test: big
1352025-01-28T21:54:42.862ZCompleted test: big
1362025-01-28T21:54:47.869ZRunning test: dep
1372025-01-28T21:55:00.637ZCompleted test: dep
1382025-01-28T21:55:05.643ZRunning test: balloon
1392025-01-28T21:55:15.323ZCompleted test: balloon
1402025-01-28T21:55:20.330ZRunning test: deactivate
1412025-01-28T21:56:14.534ZCompleted test: deactivate
1422025-01-28T21:56:19.541ZRunning hammer
1432025-01-28T21:56:22.505ZRun repair tests
1442025-01-28T21:56:22.508Z/var/tmp/bins/crutest fill -g 31 -q --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file
1452025-01-28T21:56:22.566Z{"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-01-28T21:56:21.097073138Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"task":"crutest"}
1462025-01-28T21:56:22.569Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.097740579Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"task":"crutest"}
1472025-01-28T21:56:22.569Z{"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-01-28T21:56:21.099443001Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"task":"crutest"}
1482025-01-28T21:56:22.569Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.099643419Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226}
1492025-01-28T21:56:22.570Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"7817632486f84ab6865c5ce71e16196ec0c710fc\",\n git_commit_timestamp: \"2025-01-28T21:38:04.000000000Z\",\n git_branch: \"mkeeter/early-io-rejection\",\n rustc_semver: \"1.84.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"9fc6b43126469e3858e2fe86cafb4f0fd5068869\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: true,\n opt_level: 0,\n}","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.099696406Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226}
1502025-01-28T21:56:22.570Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.099726025Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226}
1512025-01-28T21:56:22.570Z{"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 10, shift: 12 }, extent_count: 5, uuid: 00000000-0000-0000-0000-000000000000, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.099745313Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226}
1522025-01-28T21:56:22.570Z{"msg":"Crucible 6da0f61f-826d-482e-a761-8e909e0216ff has session id: 772f3a88-7909-45c7-aa2f-73bffe9c9255","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.100226165Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1532025-01-28T21:56:22.570Z{"msg":"Upstairs opts: Upstairs UUID: 6da0f61f-826d-482e-a761-8e909e0216ff, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.100281732Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1542025-01-28T21:56:22.570Z{"msg":"Crucible stats registered with UUID: 6da0f61f-826d-482e-a761-8e909e0216ff","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.1003142Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1552025-01-28T21:56:22.570Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-01-28T21:56:21.100337579Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1562025-01-28T21:56:22.573Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101375919Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"task":"crutest"}
1572025-01-28T21:56:22.573Z{"msg":"The guest has requested activation with gen:31","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101441365Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226}
1582025-01-28T21:56:22.573Z{"msg":"6da0f61f-826d-482e-a761-8e909e0216ff active request set","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101476383Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1592025-01-28T21:56:22.573Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101501332Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"0","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1602025-01-28T21:56:22.573Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101551999Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"0","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1612025-01-28T21:56:22.573Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101595426Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"1","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1622025-01-28T21:56:22.573Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101638524Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"1","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1632025-01-28T21:56:22.573Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101676592Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"2","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1642025-01-28T21:56:22.573Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.10170941Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"2","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1652025-01-28T21:56:22.573Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101746198Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"io task","client":"2","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1662025-01-28T21:56:22.573Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101772946Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"io task","client":"0","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1672025-01-28T21:56:22.573Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101808584Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"io task","client":"1","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1682025-01-28T21:56:22.574Z{"msg":"ds_connection connected from Ok(127.0.0.1:54491)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101833393Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"io task","client":"2","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1692025-01-28T21:56:22.574Z{"msg":"ds_connection connected from Ok(127.0.0.1:49989)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.101857851Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"io task","client":"1","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1702025-01-28T21:56:22.574Z{"msg":"ds_connection connected from Ok(127.0.0.1:64066)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.10188197Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"io task","client":"0","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1712025-01-28T21:56:22.574Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.102498364Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"2","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1722025-01-28T21:56:22.574Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.102534062Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"1","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1732025-01-28T21:56:22.574Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.102550301Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"0","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1742025-01-28T21:56:22.574Z{"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-01-28T21:56:21.103132157Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"1","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1752025-01-28T21:56:22.574Z{"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-01-28T21:56:21.103193144Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"0","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1762025-01-28T21:56:22.574Z{"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-01-28T21:56:21.10325915Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"2","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1772025-01-28T21:56:22.574Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103571462Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1782025-01-28T21:56:22.574Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.10361446Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1792025-01-28T21:56:22.574Z{"msg":"[0]R flush_numbers: [1498, 1498, 1498, 1498, 1498]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103639528Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1802025-01-28T21:56:22.574Z{"msg":"[0]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103674726Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1812025-01-28T21:56:22.574Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103710644Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1822025-01-28T21:56:22.574Z{"msg":"[1]R flush_numbers: [1498, 1498, 1498, 1498, 1498]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103746812Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1832025-01-28T21:56:22.574Z{"msg":"[1]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103770061Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1842025-01-28T21:56:22.574Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103805069Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1852025-01-28T21:56:22.577Z{"msg":"[2]R flush_numbers: [1498, 1498, 1498, 1498, 1498]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103840677Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1862025-01-28T21:56:22.577ZWait for a query_work_queue command to finish before sending IO
1872025-01-28T21:56:22.577Z{"msg":"[2]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103882344Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1882025-01-28T21:56:22.577Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103922892Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1892025-01-28T21:56:22.578Z{"msg":"Max found gen is 26","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.10395977Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1902025-01-28T21:56:22.578Z{"msg":"Generation requested: 31 >= found:26","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.103995968Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1912025-01-28T21:56:22.578Z{"msg":"Next flush: 1499","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.104032625Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1922025-01-28T21:56:22.578Z{"msg":"All extents match","v":0,"name":"crucible","level":30Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
1932025-01-28T21:56:22.578Z,"time":"2025-01-28T21:56:21.104058544Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"":"downstairs","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1942025-01-28T21:56:22.578Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.104090202Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1952025-01-28T21:56:22.578ZFill test
1962025-01-28T21:56:22.579Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.10412076Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"0","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1972025-01-28T21:56:22.579Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.10413591Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"1","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1982025-01-28T21:56:22.579Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.104155938Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"client":"2","":"downstairs","session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
1992025-01-28T21:56:22.579Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.104169258Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
2002025-01-28T21:56:22.579Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.104181567Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
2012025-01-28T21:56:22.579Z{"msg":"6da0f61f-826d-482e-a761-8e909e0216ff is now active with session: 772f3a88-7909-45c7-aa2f-73bffe9c9255","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.104201646Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
2022025-01-28T21:56:22.579Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.104213855Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226,"session_id":"772f3a88-7909-45c7-aa2f-73bffe9c9255"}
2032025-01-28T21:56:22.579Z{"msg":"The guest has finished waiting for activation with:31","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:21.104225634Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1226}
2042025-01-28T21:56:22.581ZRead and Verify all blocks (0..50 range:false)
2052025-01-28T21:56:22.585ZWrote out file "/var/tmp/test_up-build/verify_file"
2062025-01-28T21:56:22.585ZCLIENT: Tests done. All submitted work has been ACK'd
2072025-01-28T21:56:22.588Z----------------------------------------------------------------
2082025-01-28T21:56:22.588Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:1
2092025-01-28T21:56:22.588ZStates: Active Active Active
2102025-01-28T21:56:22.588ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2112025-01-28T21:56:22.588Z 1002 Acked Read 50 Done Done Done false
2122025-01-28T21:56:22.588Z STATES DS:0 DS:1 DS:2 TOTAL
2132025-01-28T21:56:22.588Z Sent 0 0 0 0
2142025-01-28T21:56:22.588Z Done 1 1 1 3
2152025-01-28T21:56:22.588Z Skipped 0 0 0 0
2162025-01-28T21:56:22.588Z Error 0 0 0 0
2172025-01-28T21:56:22.588ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
2182025-01-28T21:56:22.588ZDownstairs last five completed: 1001 1000
2192025-01-28T21:56:22.588ZUpstairs last five completed: 1002 1001 1000
2202025-01-28T21:56:22.588ZCLIENT: Up:0 ds:1 act:3
2212025-01-28T21:56:26.587Z----------------------------------------------------------------
2222025-01-28T21:56:26.588Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:0
2232025-01-28T21:56:26.588ZDownstairs last five completed: 1003 1002 1001 1000
2242025-01-28T21:56:26.588ZUpstairs last five completed: 1003 1002 1001 1000
2252025-01-28T21:56:26.588ZCLIENT: Up:0 ds:0 act:3
2262025-01-28T21:56:26.588ZCLIENT: All crucible jobs finished, exiting program
2272025-01-28T21:56:26.598ZRepair setup passed
2282025-01-28T21:56:26.602ZCopy the region for /var/tmp/test_up-build/8830
2292025-01-28T21:56:26.604Zcp -r /var/tmp/test_up-build/8830 /var/tmp/test_up-build/previous
2302025-01-28T21:56:26.607Z/var/tmp/bins/crutest fill -g 32 -q --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
2312025-01-28T21:56:26.664Z{"msg":"Use this region info from dsc: RegionExtentInfo { block_size: 4096, blocks_per_extent: 10, extent_count: 5 }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.194692927Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"task":"crutest"}
2322025-01-28T21:56:26.667Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.195217477Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"task":"crutest"}
2332025-01-28T21:56:26.667Z{"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-01-28T21:56:25.196935268Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"task":"crutest"}
2342025-01-28T21:56:26.667Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.197168254Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232}
2352025-01-28T21:56:26.667Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"7817632486f84ab6865c5ce71e16196ec0c710fc\",\n git_commit_timestamp: \"2025-01-28T21:38:04.000000000Z\",\n git_branch: \"mkeeter/early-io-rejection\",\n rustc_semver: \"1.84.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"9fc6b43126469e3858e2fe86cafb4f0fd5068869\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: true,\n opt_level: 0,\n}","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.197219801Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232}
2362025-01-28T21:56:26.667Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.19724855Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232}
2372025-01-28T21:56:26.667Z{"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 10, shift: 12 }, extent_count: 5, uuid: 00000000-0000-0000-0000-000000000000, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.197267418Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232}
2382025-01-28T21:56:26.667Z{"msg":"Crucible 92874a17-cb68-48cb-9791-4927dbe28afb has session id: f1f084c6-84f5-45fc-bedd-8e9c1b282982","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.197800628Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2392025-01-28T21:56:26.668Z{"msg":"Upstairs opts: Upstairs UUID: 92874a17-cb68-48cb-9791-4927dbe28afb, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.197868064Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2402025-01-28T21:56:26.668Z{"msg":"Crucible stats registered with UUID: 92874a17-cb68-48cb-9791-4927dbe28afb","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.197909411Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2412025-01-28T21:56:26.671Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-01-28T21:56:25.197946579Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2422025-01-28T21:56:26.671Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.198748103Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"task":"crutest"}
2432025-01-28T21:56:26.671Z{"msg":"The guest has requested activation with gen:32","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.1988046Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232}
2442025-01-28T21:56:26.671Z{"msg":"92874a17-cb68-48cb-9791-4927dbe28afb active request set","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.198862746Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2452025-01-28T21:56:26.671Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.198893264Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"0","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2462025-01-28T21:56:26.671Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.198943492Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"0","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2472025-01-28T21:56:26.671Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.19897085Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"1","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2482025-01-28T21:56:26.671Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.199014797Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"1","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2492025-01-28T21:56:26.671Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.199040536Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"2","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2502025-01-28T21:56:26.671Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.199064465Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"2","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2512025-01-28T21:56:26.671Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.199086423Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"io task","client":"2","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2522025-01-28T21:56:26.671Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.199119831Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"io task","client":"0","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2532025-01-28T21:56:26.671Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.19914492Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"io task","client":"1","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2542025-01-28T21:56:26.671Z{"msg":"ds_connection connected from Ok(127.0.0.1:38756)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.199426124Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"io task","client":"2","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2552025-01-28T21:56:26.671Z{"msg":"ds_connection connected from Ok(127.0.0.1:62530)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.19949374Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"io task","client":"0","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2562025-01-28T21:56:26.672Z{"msg":"ds_connection connected from Ok(127.0.0.1:51610)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.199523628Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"io task","client":"1","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2572025-01-28T21:56:26.672Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.200030199Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"1","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2582025-01-28T21:56:26.672Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.200072796Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"2","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2592025-01-28T21:56:26.672Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.200089575Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"0","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2602025-01-28T21:56:26.672Z{"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-01-28T21:56:25.200686291Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"0","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2612025-01-28T21:56:26.672Z{"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-01-28T21:56:25.200789375Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"1","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2622025-01-28T21:56:26.672Z{"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-01-28T21:56:25.201020812Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"2","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2632025-01-28T21:56:26.672Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201194971Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2642025-01-28T21:56:26.672Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201231679Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2652025-01-28T21:56:26.672Z{"msg":"[0]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201363282Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2662025-01-28T21:56:26.672Z{"msg":"[0]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201418329Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2672025-01-28T21:56:26.672Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201459436Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2682025-01-28T21:56:26.672Z{"msg":"[1]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201479455Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2692025-01-28T21:56:26.672Z{"msg":"[1]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201508683Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2702025-01-28T21:56:26.672Z{"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
2712025-01-28T21:56:26.672Z,"time":"2025-01-28T21:56:25.201525363Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2722025-01-28T21:56:26.672Z{"msg":"[2]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.20155741Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2732025-01-28T21:56:26.672Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201588849Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2742025-01-28T21:56:26.675Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201620007Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2752025-01-28T21:56:26.675Z{"msg":"Max found gen is 32","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201665584Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2762025-01-28T21:56:26.675Z{"msg":"Generation requested: 32 >= found:32","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201693103Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2772025-01-28T21:56:26.675Z{"msg":"Next flush: 1500","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201715731Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2782025-01-28T21:56:26.675Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201747359Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"":"downstairs","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2792025-01-28T21:56:26.675Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201769798Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2802025-01-28T21:56:26.675Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201803086Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"0","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2812025-01-28T21:56:26.675Z"}
2822025-01-28T21:56:26.675Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201832145Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"1","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2832025-01-28T21:56:26.675Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201861013Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"client":"2","":"downstairs","session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2842025-01-28T21:56:26.675Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201875362Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2852025-01-28T21:56:26.675Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201887522Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2862025-01-28T21:56:26.675Z{"msg":"92874a17-cb68-48cb-9791-4927dbe28afb is now active with session: f1f084c6-84f5-45fc-bedd-8e9c1b282982","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.2019079Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2872025-01-28T21:56:26.675Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201920489Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232,"session_id":"f1f084c6-84f5-45fc-bedd-8e9c1b282982"}
2882025-01-28T21:56:26.675Z{"msg":"The guest has finished waiting for activation with:32","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:25.201932579Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1232}
2892025-01-28T21:56:26.675ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
2902025-01-28T21:56:26.675ZFill test
2912025-01-28T21:56:26.678ZRead and Verify all blocks (0..50 range:false)
2922025-01-28T21:56:26.682ZWrote out file "/var/tmp/test_up-build/verify_file"
2932025-01-28T21:56:26.682ZCLIENT: Tests done. All submitted work has been ACK'd
2942025-01-28T21:56:26.685Z----------------------------------------------------------------
2952025-01-28T21:56:26.685Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:1
2962025-01-28T21:56:26.685ZStates: Active Active Active
2972025-01-28T21:56:26.685ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2982025-01-28T21:56:26.685Z 1002 Acked Read 50 Done Done Done false
2992025-01-28T21:56:26.685Z STATES DS:0 DS:1 DS:2 TOTAL
3002025-01-28T21:56:26.686Z Sent 0 0 0 0
3012025-01-28T21:56:26.686Z Done 1 1 1 3
3022025-01-28T21:56:26.686Z Skipped 0 0 0 0
3032025-01-28T21:56:26.686Z Error 0 0 0 0
3042025-01-28T21:56:26.686ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
3052025-01-28T21:56:26.686ZDownstairs last five completed: 1001 1000
3062025-01-28T21:56:26.686ZUpstairs last five completed: 1002 1001 1000
3072025-01-28T21:56:26.686ZCLIENT: Up:0 ds:1 act:3
3082025-01-28T21:56:30.683Z----------------------------------------------------------------
3092025-01-28T21:56:30.684Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:0
3102025-01-28T21:56:30.684ZDownstairs last five completed: 1003 1002 1001 1000
3112025-01-28T21:56:30.684ZUpstairs last five completed: 1003 1002 1001 1000
3122025-01-28T21:56:30.684ZCLIENT: Up:0 ds:0 act:3
3132025-01-28T21:56:30.684ZCLIENT: All crucible jobs finished, exiting program
3142025-01-28T21:56:30.690ZRepair part 1 passed
3152025-01-28T21:56:30.692Z
3162025-01-28T21:56:30.692ZKill the current downstairs
3172025-01-28T21:56:30.859ZDownstairs 2 stopped
3182025-01-28T21:56:30.859Zmv /var/tmp/test_up-build/8830 /var/tmp/test_up-build/new
3192025-01-28T21:56:30.862ZNow put back the original so we have a mismatch
3202025-01-28T21:56:30.862Zmv /var/tmp/test_up-build/previous /var/tmp/test_up-build/8830
3212025-01-28T21:56:30.865ZRestart downstairs with old directory
3222025-01-28T21:56:30.920Z/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
3232025-01-28T21:56:30.937ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
3242025-01-28T21:56:30.940Z 0 000-009 32 32 31 1500 1500 1499 F F F <---
3252025-01-28T21:56:30.940Z 1 010-019 32 32 31 1500 1500 1499 F F F <---
3262025-01-28T21:56:30.940Z 2 020-029 32 32 31 1500 1500 1499 F F F <---
3272025-01-28T21:56:30.940Z 3 030-039 32 32 31 1500 1500 1499 F F F <---
3282025-01-28T21:56:30.940Z 4 040-049 32 32 31 1500 1500 1499 F F F <---
3292025-01-28T21:56:30.940ZMax gen: 32, Max flush: 1500
3302025-01-28T21:56:31.152ZError: Difference in extent metadata found!
3312025-01-28T21:56:31.152Z
3322025-01-28T21:56:31.152ZStack backtrace:
3332025-01-28T21:56:31.152Z 0: anyhow::error::<impl anyhow::Error>::msg
3342025-01-28T21:56:31.152Z at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.92/src/backtrace.rs:27:14
3352025-01-28T21:56:31.152Z 1: anyhow::__private::format_err
3362025-01-28T21:56:31.152Z at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.92/src/lib.rs:691:13
3372025-01-28T21:56:31.169Zdump test found error as expected
3382025-01-28T21:56:31.169Z
3392025-01-28T21:56:31.169Z
3402025-01-28T21:56:31.172Z/var/tmp/bins/crutest verify --range -g 33 -q --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
3412025-01-28T21:56:31.227Z{"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-01-28T21:56:29.756945692Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"task":"crutest"}
3422025-01-28T21:56:31.230Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.757493941Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"task":"crutest"}
3432025-01-28T21:56:31.230Z{"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-01-28T21:56:29.759130036Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"task":"crutest"}
3442025-01-28T21:56:31.231Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.759346264Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240}
3452025-01-28T21:56:31.231Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"7817632486f84ab6865c5ce71e16196ec0c710fc\",\n git_commit_timestamp: \"2025-01-28T21:38:04.000000000Z\",\n git_branch: \"mkeeter/early-io-rejection\",\n rustc_semver: \"1.84.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"9fc6b43126469e3858e2fe86cafb4f0fd5068869\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: true,\n opt_level: 0,\n}","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.759391701Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240}
3462025-01-28T21:56:31.231Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.759415Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240}
3472025-01-28T21:56:31.231Z{"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 10, shift: 12 }, extent_count: 5, uuid: 00000000-0000-0000-0000-000000000000, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.759430649Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240}
3482025-01-28T21:56:31.231Z{"msg":"Crucible 7a233090-93a2-4dfb-95c4-c5f6abfa92e9 has session id: 236e860a-d753-4744-8342-2e021e34c0ff","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.76010336Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3492025-01-28T21:56:31.234Z{"msg":"Upstairs opts: Upstairs UUID: 7a233090-93a2-4dfb-95c4-c5f6abfa92e9, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.760157667Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3502025-01-28T21:56:31.234Z{"msg":"Crucible stats registered with UUID: 7a233090-93a2-4dfb-95c4-c5f6abfa92e9","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.760192835Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3512025-01-28T21:56:31.234Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-01-28T21:56:29.760209304Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3522025-01-28T21:56:31.234Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761248284Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"task":"crutest"}
3532025-01-28T21:56:31.234Z{"msg":"The guest has requested activation with gen:33","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761282982Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240}
3542025-01-28T21:56:31.234Z{"msg":"7a233090-93a2-4dfb-95c4-c5f6abfa92e9 active request set","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761345298Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3552025-01-28T21:56:31.234Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761363337Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"0","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3562025-01-28T21:56:31.234Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761388695Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"0","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3572025-01-28T21:56:31.234Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761404075Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"1","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3582025-01-28T21:56:31.234Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761418434Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"1","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3592025-01-28T21:56:31.234Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761441852Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3602025-01-28T21:56:31.234Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761456831Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3612025-01-28T21:56:31.234Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761470681Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3622025-01-28T21:56:31.234Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761502009Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"0","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3632025-01-28T21:56:31.234Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761533537Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"1","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3642025-01-28T21:56:31.234Z{"msg":"ds_connection connected from Ok(127.0.0.1:64576)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761564195Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"1","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3652025-01-28T21:56:31.235Z{"msg":"ds_connection connected from Ok(127.0.0.1:37587)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761597183Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"0","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3662025-01-28T21:56:31.235Z{"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-01-28T21:56:29.761750625Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3672025-01-28T21:56:31.235Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2025-01-28T21:56:29.761883837Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3682025-01-28T21:56:31.235Z{"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-01-28T21:56:29.761926024Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3692025-01-28T21:56:31.235Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.761949563Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3702025-01-28T21:56:31.235Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.762270464Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"1","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3712025-01-28T21:56:31.235Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.762319842Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"0","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3722025-01-28T21:56:31.235Z{"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-01-28T21:56:29.762881829Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"1","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3732025-01-28T21:56:31.235Z{"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-01-28T21:56:29.762924387Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"0","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3742025-01-28T21:56:31.235Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.763292476Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3752025-01-28T21:56:31.235Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:29.763335833Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3762025-01-28T21:56:41.234Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.762989348Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3772025-01-28T21:56:41.234Z{"msg":"ds_connection connected from Ok(127.0.0.1:50265)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.763106932Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"io task","client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3782025-01-28T21:56:41.239Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.764032608Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3792025-01-28T21:56:41.239Z{"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-01-28T21:56:39.764651032Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3802025-01-28T21:56:41.240Z{"msg":"[0]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765080938Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3812025-01-28T21:56:41.240Z{"msg":"[0]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765118215Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3822025-01-28T21:56:41.240Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765136374Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3832025-01-28T21:56:41.240Z{"msg":"[1]R flush_numbers: [1500, 1500, 1500, 1500, 1500]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765152493Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3842025-01-28T21:56:41.240Z{"msg":"[1]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765167122Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3852025-01-28T21:56:41.240Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765189451Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3862025-01-28T21:56:41.240Z{"msg":"[2]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.76520343Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3872025-01-28T21:56:41.240Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765217359Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3882025-01-28T21:56:41.240Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765240578Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3892025-01-28T21:56:41.240Z{"msg":"Max found gen is 33","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765254427Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3902025-01-28T21:56:41.240Z{"msg":"Generation requested: 33 >= found:33","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765276916Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3912025-01-28T21:56:41.240Z{"msg":"Next flush: 1501","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765291785Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3922025-01-28T21:56:41.240Z{"msg":"extent 0 needs reconciliation: ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 31, flush: 1499, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765315644Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3932025-01-28T21:56:41.240Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 31, flush: 1499, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765334013Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3942025-01-28T21:56:41.240Z{"msg":"found dest for source 0 for extent at index 0 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765355762Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3952025-01-28T21:56:41.240Z{"msg":"extent 1 needs reconciliation: ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 31, flush: 1499, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.76537231Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3962025-01-28T21:56:41.240Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 31, flush: 1499, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765389Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3972025-01-28T21:56:41.240Z{"msg":"found dest for source 0 for extent at index 1 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765403679Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3982025-01-28T21:56:41.240Z{"msg":"extent 2 needs reconciliation: ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 31, flush: 1499, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765428867Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
3992025-01-28T21:56:41.241Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 31, flush: 1499, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765445356Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4002025-01-28T21:56:41.241Z{"msg":"found dest for source 0 for extent at index 2 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765467675Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4012025-01-28T21:56:41.241Z{"msg":"extent 3 needs reconciliation: ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 31, flush: 1499, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765484264Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4022025-01-28T21:56:41.241Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 31, flush: 1499, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765507403Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4032025-01-28T21:56:41.241Z{"msg":"found dest for source 0 for extent at index 3 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765521902Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4042025-01-28T21:56:41.241Z{"msg":"extent 4 needs reconciliation: ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 32, flush: 1500, dirty: false } ExtentMetadata { gen: 31, flush: 1499, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765545311Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4052025-01-28T21:56:41.241Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 32, flush: 1500, dirty: false }, ExtentMetadata { gen: 31, flush: 1499, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.76556087Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4062025-01-28T21:56:41.241Z{"msg":"found dest for source 0 for extent at index 4 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765582629Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"mend","":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4072025-01-28T21:56:41.241Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765607187Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"0","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4082025-01-28T21:56:41.241Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765642715Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"1","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4092025-01-28T21:56:41.241Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765663984Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4102025-01-28T21:56:41.241Z{"msg":"Full repair list: {ExtentId(0): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(3): 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)] }}","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765689762Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4112025-01-28T21:56:41.241Z{"msg":"Task list: [ReconcileIO { id: ReconciliationId(0), op: ExtentFlush { repair_id: ReconciliationId(0), extent_id: ExtentId(0), client_id: ClientId(0), flush_number: 1501, 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(3), client_id: ClientId(0), flush_number: 1501, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(5), op: ExtentClose { repair_id: ReconciliationId(5), extent_id: ExtentId(3) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(6), op: ExtentRepair { repair_id: ReconciliationId(6), 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(7), op: ExtentReopen { repair_id: ReconciliationId(7), extent_id: ExtentId(3) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(8), op: ExtentFlush { repair_id: ReconciliationId(8), extent_id: ExtentId(2), client_id: ClientId(0), flush_number: 1501, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(9), op: ExtentClose { repair_id: ReconciliationId(9), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(10), op: ExtentRepair { repair_id: ReconciliationId(10), 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(11), op: ExtentReopen { repair_id: ReconciliationId(11), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(12), op: ExtentFlush { repair_id: ReconciliationId(12), extent_id: ExtentId(1), client_id: ClientId(0), flush_number: 1501, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(13), op: ExtentClose { repair_id: ReconciliationId(13), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(14), op: ExtentRepair { repair_id: ReconciliationId(14), extent_id: ExtentId(1), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(15), op: ExtentReopen { repair_id: ReconciliationId(15), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(16), op: ExtentFlush { repair_id: ReconciliationId(16), extent_id: ExtentId(4), client_id: ClientId(0), flush_number: 1501, 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-01-28T21:56:39.765792216Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4122025-01-28T21:56:41.241Z{"msg":"starting reconciliation 457f5710-7875-4bef-8ba8-435f948633a2: found 20 extents that need repair","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765810275Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4132025-01-28T21:56:41.241Z{"msg":"sending reconcile request ReconciliationId(2)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.765975496Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4142025-01-28T21:56:41.248Z{"msg":"sending reconcile request ReconciliationId(6)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.777167918Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4152025-01-28T21:56:41.252Z{"msg":"sending reconcile request ReconciliationId(10)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.780968939Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4162025-01-28T21:56:41.256Z{"msg":"sending reconcile request ReconciliationId(14)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.784858964Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4172025-01-28T21:56:41.259Z{"msg":"sending reconcile request ReconciliationId(18)","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.788447396Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4182025-01-28T21:56:41.262Z{"msg":"done with reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.791382126Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"":"downstairs","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4192025-01-28T21:56:41.262Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.791419844Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"0","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4202025-01-28T21:56:41.263Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.791435894Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"1","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4212025-01-28T21:56:41.263Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.791450393Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"client":"2","":"downstairs","session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4222025-01-28T21:56:41.265Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.791465982Z"Wait for a query_work_queue command to finish before sending IO
4232025-01-28T21:56:41.265Z,"hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4242025-01-28T21:56:41.265Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.79149452Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4252025-01-28T21:56:41.265Z{"msg":"7a233090-93a2-4dfb-95c4-c5f6abfa92e9 is now active with session: 236e860a-d753-4744-8342-2e021e34c0ff","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.791529428Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240,"session_id":"236e860a-d753-4744-8342-2e021e34c0ff"}
4262025-01-28T21:56:41.265Z{"msg":"The guest has finished waiting for activation with:33","v":0,"name":"crucible","level":30,"time":"2025-01-28T21:56:39.791565006Z","hostname":"w-01JJQEEJV9J7Q4F56MKK1TGX8C","pid":1240}
4272025-01-28T21:56:41.266ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
4282025-01-28T21:56:41.266ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
4292025-01-28T21:56:41.266ZRead and Verify all blocks (0..50 range:true)
4302025-01-28T21:56:41.270ZWrote out file "/var/tmp/test_up-build/verify_file"
4312025-01-28T21:56:41.270ZVerify test completed
4322025-01-28T21:56:41.272ZWrote out file "/var/tmp/test_up-build/verify_file"
4332025-01-28T21:56:41.272ZCLIENT: Tests done. All submitted work has been ACK'd
4342025-01-28T21:56:41.272Z----------------------------------------------------------------
4352025-01-28T21:56:41.272Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:1
4362025-01-28T21:56:41.272ZStates: Active Active Active
4372025-01-28T21:56:41.273ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
4382025-01-28T21:56:41.273Z 1000 Acked Read 50 Done Done Done false
4392025-01-28T21:56:41.273Z STATES DS:0 DS:1 DS:2 TOTAL
4402025-01-28T21:56:41.273Z Sent 0 0 0 0
4412025-01-28T21:56:41.273Z Done 1 1 1 3
4422025-01-28T21:56:41.273Z Skipped 0 0 0 0
4432025-01-28T21:56:41.273Z Error 0 0 0 0
4442025-01-28T21:56:41.273ZLast Flush: None None None
4452025-01-28T21:56:41.273ZDownstairs last five completed:
4462025-01-28T21:56:41.273ZUpstairs last five completed: 1000
4472025-01-28T21:56:41.273ZCLIENT: Up:0 ds:1 act:3
4482025-01-28T21:56:45.271Z----------------------------------------------------------------
4492025-01-28T21:56:45.271Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:0
4502025-01-28T21:56:45.271ZDownstairs last five completed: 1001 1000
4512025-01-28T21:56:45.271ZUpstairs last five completed: 1001 1000
4522025-01-28T21:56:45.271ZCLIENT: Up:0 ds:0 act:3
4532025-01-28T21:56:45.271ZCLIENT: All crucible jobs finished, exiting program
4542025-01-28T21:56:45.280ZRepair part 2 passed
4552025-01-28T21:56:45.282Z/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
4562025-01-28T21:56:45.296ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
4572025-01-28T21:56:45.297Z 0 000-009 32 32 32 1500 1500 1500 F F F
4582025-01-28T21:56:45.297Z 1 010-019 32 32 32 1500 1500 1500 F F F
4592025-01-28T21:56:45.297Z 2 020-029 32 32 32 1500 1500 1500 F F F
4602025-01-28T21:56:45.297Z 3 030-039 32 32 32 1500 1500 1500 F F F
4612025-01-28T21:56:45.297Z 4 040-049 32 32 32 1500 1500 1500 F F F
4622025-01-28T21:56:45.297ZMax gen: 32, Max flush: 1500
4632025-01-28T21:56:45.300Zdump test passed
4642025-01-28T21:56:45.303Z/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
4652025-01-28T21:56:45.316Z Extent 1
4662025-01-28T21:56:45.319ZGEN 32 32 32
4672025-01-28T21:56:45.319ZFLUSH_ID 1500 1500 1500
4682025-01-28T21:56:45.319ZDIRTY
4692025-01-28T21:56:45.319Z
4702025-01-28T21:56:45.319ZBLOCK D0 D1 D2 C0 C1 C2 DIFF
4712025-01-28T21:56:45.319Z010 A A A A A A
4722025-01-28T21:56:45.322Z011 A A A A A A
4732025-01-28T21:56:45.322Z012 A A A A A A
4742025-01-28T21:56:45.325Z013 A A A A A A
4752025-01-28T21:56:45.325Z014 A A A A A A
4762025-01-28T21:56:45.327Z015 A A A A A A
4772025-01-28T21:56:45.327Z016 A A A A A A
4782025-01-28T21:56:45.330Z017 A A A A A A
4792025-01-28T21:56:45.330Z018 A A A A A A
4802025-01-28T21:56:45.332Z019 A A A A A A
4812025-01-28T21:56:45.335Zdump extent test passed
4822025-01-28T21:56:45.335Z/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
4832025-01-28T21:56:45.349ZExtent 2 Block in extent 0 Actual block 20
4842025-01-28T21:56:45.349Z
4852025-01-28T21:56:45.351Z DATA SHA256 VER
4862025-01-28T21:56:45.351Z------ ---------------------------------------------------------------- ---
4872025-01-28T21:56:45.352Z 0 ad3d0e88276af7eb1f904413516e1a8c1f9c2fa8b17b86b2d842d08303e90aa2 A
4882025-01-28T21:56:45.352Z 1 ad3d0e88276af7eb1f904413516e1a8c1f9c2fa8b17b86b2d842d08303e90aa2 A
4892025-01-28T21:56:45.355Z 2 ad3d0e88276af7eb1f904413516e1a8c1f9c2fa8b17b86b2d842d08303e90aa2 A
4902025-01-28T21:56:45.355Z
4912025-01-28T21:56:45.355ZNONCES 0 1 2 DIFF
4922025-01-28T21:56:45.355Z------ ------------------------ ------------------------ ------------------------ -----
4932025-01-28T21:56:45.355Z
4942025-01-28T21:56:45.355Z TAGS 0 1 2 DIFF
4952025-01-28T21:56:45.355Z------ -------------------------------- -------------------------------- -------------------------------- -----
4962025-01-28T21:56:45.355Z
4972025-01-28T21:56:45.355ZHASHES 0 1 2 DIFF
4982025-01-28T21:56:45.356Z------ ---------------- ---------------- ---------------- -----
4992025-01-28T21:56:45.356Z 0 42916ab6fa364c70 42916ab6fa364c70 42916ab6fa364c70
5002025-01-28T21:56:45.356Z
5012025-01-28T21:56:45.359Zdump block test passed
5022025-01-28T21:56:45.359ZInitial upstairs tests have completed, stopping all downstairs
5032025-01-28T21:56:50.419ZCreating 4 larger downstairs regions
5042025-01-28T21:56:50.536ZStarting 4 downstairs
5052025-01-28T21:56:55.543Zdsc restarted at PID: 1253
5062025-01-28T21:56:55.777ZNow do the replace-reconcile test
5072025-01-28T21:56:55.834ZUsing 8840 for the replacement port
5082025-01-28T21:59:45.243ZCompleted test: replace-reconcile
5092025-01-28T21:59:46.249ZNow do the replace-before-active test
5102025-01-28T22:02:29.682ZCompleted test: replace-before-active
5112025-01-28T22:02:29.683ZAll tests have completed, stopping all downstairs
5122025-01-28T22:02:29.741Z
5132025-01-28T22:02:29.741ZAll Tests have passed
5142025-01-28T22:02:29.744Z8:06 Test duration
5152025-01-28T22:02:29.744Z
5162025-01-28T22:02:29.744Zreal 8:05.698954995
5172025-01-28T22:02:29.744Zuser 1:03.423950121
5182025-01-28T22:02:29.744Zsys 10.002957340
5192025-01-28T22:02:29.744Ztrap 0.084478521
5202025-01-28T22:02:29.744Ztflt 0.014859550
5212025-01-28T22:02:29.744Zdflt 0.017733208
5222025-01-28T22:02:29.744Zkflt 0.001245576
5232025-01-28T22:02:29.744Zlock 5:45:53.333314712
5242025-01-28T22:02:29.744Zslp 24:59.922653825
5252025-01-28T22:02:29.744Zlat 7.798682969
5262025-01-28T22:02:29.744Zstop 0.129059001
5272025-01-28T22:02:29.744Z+ echo 'test-up-unencrypted ends'
5282025-01-28T22:02:29.744Ztest-up-unencrypted ends
5292025-01-28T22:02:34.747Zprocess exited: duration 494160 ms, exit code 0
5302025-01-28T22:02:34.747Zexec warning: : stdio descriptors remain open after task exit; waiting 60 seconds for them to close
5312025-01-28T22:03:34.790Zexec warning: : stdout descriptor may be held open by a background process; giving up!
5322025-01-28T22:03:34.790Zexec warning: : stderr descriptor may be held open by a background process; giving up!
 
5332025-01-28T22:03:34.813Zfound 14 output files
5342025-01-28T22:03:34.813Zuploading: /tmp/test_up-build/dsc-out.txt (39466 bytes)
5352025-01-28T22:03:35.831Zuploaded: /tmp/test_up-build/dsc-out.txt
5362025-01-28T22:03:35.831Zuploading: /tmp/test_up-build/test_up_out.txt (7793132 bytes)
5372025-01-28T22:03:36.914Zuploaded: /tmp/test_up-build/test_up_out.txt
5382025-01-28T22:03:36.917Zuploading: /tmp/test_up-build/dsc/downstairs-8810.txt (2503 bytes)
5392025-01-28T22:03:37.923Zuploaded: /tmp/test_up-build/dsc/downstairs-8810.txt
5402025-01-28T22:03:37.925Zuploading: /tmp/test_up-build/dsc/downstairs-8820.txt (144657 bytes)
5412025-01-28T22:03:38.936Zuploaded: /tmp/test_up-build/dsc/downstairs-8820.txt
5422025-01-28T22:03:38.958Zuploading: /tmp/test_up-build/dsc/downstairs-8830.txt (251016 bytes)
5432025-01-28T22:03:39.969Zuploaded: /tmp/test_up-build/dsc/downstairs-8830.txt
5442025-01-28T22:03:39.971Zuploading: /tmp/test_up-build/dsc/downstairs-8840.txt (139448 bytes)
5452025-01-28T22:03:40.983Zuploaded: /tmp/test_up-build/dsc/downstairs-8840.txt
5462025-01-28T22:03:40.985Zuploading: /tmp/debug/df.txt (1270 bytes)
5472025-01-28T22:03:41.991Zuploaded: /tmp/debug/df.txt
5482025-01-28T22:03:41.993Zuploading: /tmp/debug/dtrace.txt (488936 bytes)
5492025-01-28T22:03:43.009Zuploaded: /tmp/debug/dtrace.txt
5502025-01-28T22:03:43.012Zuploading: /tmp/debug/iostat.txt (165312 bytes)
5512025-01-28T22:03:43.019Zupload warning: file "/tmp/debug/iostat.txt" changed size mid upload: 165312 -> 167712
5522025-01-28T22:03:44.025Zuploaded: /tmp/debug/iostat.txt
5532025-01-28T22:03:44.037Zuploading: /tmp/debug/mpstat.txt (401687 bytes)
5542025-01-28T22:03:44.046Zupload warning: file "/tmp/debug/mpstat.txt" changed size mid upload: 401687 -> 408248
5552025-01-28T22:03:45.049Zuploaded: /tmp/debug/mpstat.txt
5562025-01-28T22:03:45.059Zuploading: /tmp/debug/paging.txt (72213 bytes)
5572025-01-28T22:03:45.069Zupload warning: file "/tmp/debug/paging.txt" changed size mid upload: 72213 -> 73636
5582025-01-28T22:03:46.073Zuploaded: /tmp/debug/paging.txt
5592025-01-28T22:03:46.075Zuploading: /tmp/debug/prstat.txt (755693 bytes)
5602025-01-28T22:03:46.089Zupload warning: file "/tmp/debug/prstat.txt" changed size mid upload: 755693 -> 771231
5612025-01-28T22:03:47.098Zuploaded: /tmp/debug/prstat.txt
5622025-01-28T22:03:47.100Zuploading: /tmp/debug/psrinfo.txt (1528 bytes)
5632025-01-28T22:03:48.107Zuploaded: /tmp/debug/psrinfo.txt
5642025-01-28T22:03:48.114Zuploading: /tmp/debug/upstairs-info.txt (51700 bytes)
5652025-01-28T22:03:49.120Zuploaded: /tmp/debug/upstairs-info.txt