01JJMKBH0BYS2R2BGYWD7AZRMA: 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: 01JJMKBZQ2R619QXR329W670XR

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-01-27T19:34:47.457Zjob dependencies complete; ready to run (waiting for 13 m 31 s)
22025-01-27T19:36:17.921Zjob assigned to worker 01JJMM54SE509ZXJB5G5B3AP3X [factory aws, i-0232f9c52c215a036] (queued for 1 m 30 s)
32025-01-27T19:36:25.358Zdownloading input: /input/build/work/bins/crucible-downstairs.gz
42025-01-27T19:36:26.451Zdownloaded input: /input/build/work/bins/crucible-downstairs.gz
52025-01-27T19:36:26.452Zdownloading input: /input/build/work/bins/crucible-hammer.gz
62025-01-27T19:36:27.555Zdownloaded input: /input/build/work/bins/crucible-hammer.gz
72025-01-27T19:36:27.555Zdownloading input: /input/build/work/bins/crutest.gz
82025-01-27T19:36:28.698Zdownloaded input: /input/build/work/bins/crutest.gz
92025-01-27T19:36:28.699Zdownloading input: /input/build/work/bins/dsc.gz
102025-01-27T19:36:29.365Zdownloaded input: /input/build/work/bins/dsc.gz
112025-01-27T19:36:29.369Zdownloading input: /input/build/work/scripts/perf-downstairs-tick.d
122025-01-27T19:36:29.385Zdownloaded input: /input/build/work/scripts/perf-downstairs-tick.d
132025-01-27T19:36:29.385Zdownloading input: /input/build/work/scripts/test_ds.sh
142025-01-27T19:36:29.400Zdownloaded input: /input/build/work/scripts/test_ds.sh
152025-01-27T19:36:29.400Zdownloading input: /input/build/work/scripts/test_live_repair.sh
162025-01-27T19:36:29.421Zdownloaded input: /input/build/work/scripts/test_live_repair.sh
172025-01-27T19:36:29.421Zdownloading input: /input/build/work/scripts/test_repair.sh
182025-01-27T19:36:29.442Zdownloaded input: /input/build/work/scripts/test_repair.sh
192025-01-27T19:36:29.442Zdownloading input: /input/build/work/scripts/test_replay.sh
202025-01-27T19:36:29.458Zdownloaded input: /input/build/work/scripts/test_replay.sh
212025-01-27T19:36:29.458Zdownloading input: /input/build/work/scripts/test_up.sh
222025-01-27T19:36:29.476Zdownloaded input: /input/build/work/scripts/test_up.sh
232025-01-27T19:36:29.476Zdownloading input: /input/build/work/scripts/upstairs_info.d
242025-01-27T19:36:29.493Zdownloaded input: /input/build/work/scripts/upstairs_info.d
252025-01-27T19:36:29.496Zdownloading input: /input/build/tmp/cargo-test-out.log
262025-01-27T19:36:30.156Zdownloaded input: /input/build/tmp/cargo-test-out.log
 
272025-01-27T19:36:30.156Zstarting task 0: "setup"
282025-01-27T19:36:30.161Z++ uname -s
292025-01-27T19:36:30.164Z+ kern=SunOS
302025-01-27T19:36:30.164Z+ case "$kern" in
312025-01-27T19:36:30.164Z+ groupadd -g 12345 build
322025-01-27T19:36:30.166Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
332025-01-27T19:36:32.174Z+ zfs create -o mountpoint=/work rpool/work
342025-01-27T19:36:32.256Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
352025-01-27T19:36:32.259Z+ home_fs=zfs
362025-01-27T19:36:32.259Z+ [[ zfs == autofs ]]
372025-01-27T19:36:32.259Z+ mkdir -p /home/build
382025-01-27T19:36:32.262Z+ chown build:build /home/build /work
392025-01-27T19:36:34.263Z+ chmod 0700 /home/build /work
402025-01-27T19:36:34.266Zprocess exited: duration 4115 ms, exit code 0
 
412025-01-27T19:36:34.274Zstarting task 1: "authentication"
422025-01-27T19:36:34.289Zprocess exited: duration 17 ms, exit code 0
 
432025-01-27T19:36:34.295Zstarting task 2: "build"
442025-01-27T19:36:34.300Z+ banner cores
452025-01-27T19:36:34.304Z
462025-01-27T19:36:34.304Z #### #### ##### ###### ####
472025-01-27T19:36:34.304Z # # # # # # # #
482025-01-27T19:36:34.304Z # # # # # ##### ####
492025-01-27T19:36:34.304Z # # # ##### # #
502025-01-27T19:36:34.304Z # # # # # # # # #
512025-01-27T19:36:34.304Z #### #### # # ###### ####
522025-01-27T19:36:34.304Z
532025-01-27T19:36:34.307Z+ pfexec coreadm -i /tmp/core.%f.%p -g /tmp/core.%f.%p -e global -e log -e proc-setid -e global-setid
542025-01-27T19:36:34.312Z+ echo 'input bins dir contains:'
552025-01-27T19:36:34.315Zinput bins dir contains:
562025-01-27T19:36:34.315Z+ ls -ltr /input/build/work/bins
572025-01-27T19:36:34.315Ztotal 768756
582025-01-27T19:36:34.315Z-rw-r--r-- 1 root root 109552405 Jan 27 19:36 crucible-downstairs.gz
592025-01-27T19:36:34.315Z-rw-r--r-- 1 root root 104184205 Jan 27 19:36 crucible-hammer.gz
602025-01-27T19:36:34.315Z-rw-r--r-- 1 root root 113232671 Jan 27 19:36 crutest.gz
612025-01-27T19:36:34.315Z-rw-r--r-- 1 root root 66369525 Jan 27 19:36 dsc.gz
622025-01-27T19:36:34.315Z+ banner unpack
632025-01-27T19:36:34.318Z
642025-01-27T19:36:34.318Z # # # # ##### ## #### # #
652025-01-27T19:36:34.318Z # # ## # # # # # # # # #
662025-01-27T19:36:34.318Z # # # # # # # # # # ####
672025-01-27T19:36:34.318Z # # # # # ##### ###### # # #
682025-01-27T19:36:34.318Z # # # ## # # # # # # #
692025-01-27T19:36:34.318Z #### # # # # # #### # #
702025-01-27T19:36:34.318Z
712025-01-27T19:36:34.318Z+ mkdir -p /var/tmp/bins
722025-01-27T19:36:34.321Z+ for t in "$input/bins/"*.gz
732025-01-27T19:36:34.321Z++ basename /input/build/work/bins/crucible-downstairs.gz
742025-01-27T19:36:34.321Z+ b=crucible-downstairs.gz
752025-01-27T19:36:34.321Z+ b=crucible-downstairs
762025-01-27T19:36:34.321Z+ gunzip
772025-01-27T19:36:36.591Z+ chmod +x /var/tmp/bins/crucible-downstairs
782025-01-27T19:36:36.594Z+ for t in "$input/bins/"*.gz
792025-01-27T19:36:36.597Z++ basename /input/build/work/bins/crucible-hammer.gz
802025-01-27T19:36:36.597Z+ b=crucible-hammer.gz
812025-01-27T19:36:36.597Z+ b=crucible-hammer
822025-01-27T19:36:36.597Z+ gunzip
832025-01-27T19:36:38.719Z+ chmod +x /var/tmp/bins/crucible-hammer
842025-01-27T19:36:38.722Z+ for t in "$input/bins/"*.gz
852025-01-27T19:36:38.725Z++ basename /input/build/work/bins/crutest.gz
862025-01-27T19:36:38.725Z+ b=crutest.gz
872025-01-27T19:36:38.725Z+ b=crutest
882025-01-27T19:36:38.725Z+ gunzip
892025-01-27T19:36:41.102Z+ chmod +x /var/tmp/bins/crutest
902025-01-27T19:36:41.105Z+ for t in "$input/bins/"*.gz
912025-01-27T19:36:41.107Z++ basename /input/build/work/bins/dsc.gz
922025-01-27T19:36:41.107Z+ b=dsc.gz
932025-01-27T19:36:41.107Z+ b=dsc
942025-01-27T19:36:41.107Z+ gunzip
952025-01-27T19:36:42.473Z+ chmod +x /var/tmp/bins/dsc
962025-01-27T19:36:42.476Z+ export BINDIR=/var/tmp/bins
972025-01-27T19:36:42.476Z+ BINDIR=/var/tmp/bins
982025-01-27T19:36:42.476Z+ export RUST_BACKTRACE=1
992025-01-27T19:36:42.476Z+ RUST_BACKTRACE=1
1002025-01-27T19:36:42.476Z+ jobpid=1141
1012025-01-27T19:36:42.479Z+ echo 'Setup debug logging'
1022025-01-27T19:36:42.479Z+ mkdir /tmp/debug
1032025-01-27T19:36:42.479ZSetup debug logging
1042025-01-27T19:36:42.479Z+ sleep 7200
1052025-01-27T19:36:42.479Z+ psrinfo -v
1062025-01-27T19:36:42.482Z+ df -h
1072025-01-27T19:36:42.489Z+ prstat -d d -mLc 1
1082025-01-27T19:36:42.492Z+ iostat -T d -xn 1
1092025-01-27T19:36:42.492Z+ mpstat -T d 1
1102025-01-27T19:36:42.492Z+ vmstat -T d -p 1
1112025-01-27T19:36:42.494Z+ pfexec dtrace -Z -s /input/build/work/scripts/perf-downstairs-tick.d
1122025-01-27T19:36:42.494Z+ banner test_up_unencrypted
1132025-01-27T19:36:42.494Z+ pfexec dtrace -Z -s /input/build/work/scripts/upstairs_info.d
1142025-01-27T19:36:42.497Z
1152025-01-27T19:36:42.497Z ##### ###### #### ##### # # ##### # # # #
1162025-01-27T19:36:42.497Z # # # # # # # # # # ## #
1172025-01-27T19:36:42.497Z # ##### #### # # # # # # # # # #
1182025-01-27T19:36:42.497Z # # # # # # ##### # # # # #
1192025-01-27T19:36:42.497Z # # # # # # # # # # # ##
1202025-01-27T19:36:42.497Z # ###### #### # ####### #### # ####### #### # #
1212025-01-27T19:36:42.498Z
1222025-01-27T19:36:42.498Z+ ptime -m bash /input/build/work/scripts/test_up.sh -N unencrypted
1232025-01-27T19:36:42.507Z/input/build/work
1242025-01-27T19:36:42.518ZTurn off color for downstairs dump
1252025-01-27T19:36:42.521Zdsc output goes to /tmp/test_up-build/dsc-out.txt
1262025-01-27T19:36:42.521ZCreating 3 downstairs regions
1272025-01-27T19:36:42.841ZStarting 3 downstairs
1282025-01-27T19:36:42.844Zdsc started at PID: 1186
1292025-01-27T19:36:48.015ZDisable automatic restart on all downstairs
1302025-01-27T19:36:48.067Z
1312025-01-27T19:36:48.068ZBegin tests, output goes to /tmp/test_up-build/test_up_out.txt
1322025-01-27T19:36:48.071ZRunning test: span
1332025-01-27T19:36:52.173ZCompleted test: span
1342025-01-27T19:36:57.181ZRunning test: big
1352025-01-27T19:37:01.322ZCompleted test: big
1362025-01-27T19:37:06.329ZRunning test: dep
1372025-01-27T19:37:19.106ZCompleted test: dep
1382025-01-27T19:37:24.113ZRunning test: balloon
1392025-01-27T19:37:33.798ZCompleted test: balloon
1402025-01-27T19:37:38.804ZRunning test: deactivate
1412025-01-27T19:38:33.015ZCompleted test: deactivate
1422025-01-27T19:38:38.022ZRunning hammer
1432025-01-27T19:38:40.926ZRun repair tests
1442025-01-27T19:38:40.929Z/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-27T19:38:40.988Z{"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-27T19:38:39.584964034Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"task":"crutest"}
1462025-01-27T19:38:40.991Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.585499995Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"task":"crutest"}
1472025-01-27T19:38:40.991Z{"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-27T19:38:39.587201788Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"task":"crutest"}
1482025-01-27T19:38:40.991Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.587384768Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223}
1492025-01-27T19:38:40.991Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"d77aa90b6afe7d7ddb1dc63211fa4216c8866a90\",\n git_commit_timestamp: \"2025-01-27T19:20:16.000000000Z\",\n git_branch: \"mkeeter/shrink-replay-buffer\",\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-27T19:38:39.587436708Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223}
1502025-01-27T19:38:40.991Z{"msg":"Upstairs <-> Downstairs Message Version: 12","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.587463128Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223}
1512025-01-27T19:38:40.991Z{"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-27T19:38:39.587481268Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223}
1522025-01-27T19:38:40.995Z{"msg":"Crucible 571e0e0a-c0dd-403f-8fe3-f02b0e092199 has session id: b59e9705-d8cc-4289-9643-18bef427d280","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.588008969Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1532025-01-27T19:38:40.995Z{"msg":"Upstairs opts: Upstairs UUID: 571e0e0a-c0dd-403f-8fe3-f02b0e092199, 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-27T19:38:39.588061899Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1542025-01-27T19:38:40.995Z{"msg":"Crucible stats registered with UUID: 571e0e0a-c0dd-403f-8fe3-f02b0e092199","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.588089449Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1552025-01-27T19:38:40.995Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-01-27T19:38:39.588111229Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1562025-01-27T19:38:40.995Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589086931Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"task":"crutest"}
1572025-01-27T19:38:40.995Z{"msg":"The guest has requested activation with gen:31","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589126961Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223}
1582025-01-27T19:38:40.995Z{"msg":"571e0e0a-c0dd-403f-8fe3-f02b0e092199 active request set","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589168791Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1592025-01-27T19:38:40.995Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589193191Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"0","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1602025-01-27T19:38:40.995Z{"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-27T19:38:39.589217661Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"0","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1612025-01-27T19:38:40.995Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589250551Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"1","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1622025-01-27T19:38:40.995Z{"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-27T19:38:39.589271581Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"1","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1632025-01-27T19:38:40.995Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589285751Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"2","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1642025-01-27T19:38:40.995Z{"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-27T19:38:39.589299851Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"2","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1652025-01-27T19:38:40.995Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589326721Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"io task","client":"2","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1662025-01-27T19:38:40.995Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589353351Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"io task","client":"1","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1672025-01-27T19:38:40.995Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589388821Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"io task","client":"0","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1682025-01-27T19:38:40.995Z{"msg":"ds_connection connected from Ok(127.0.0.1:37553)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589425021Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"io task","client":"2","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1692025-01-27T19:38:40.995Z{"msg":"ds_connection connected from Ok(127.0.0.1:45487)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589526881Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"io task","client":"1","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1702025-01-27T19:38:40.995Z{"msg":"ds_connection connected from Ok(127.0.0.1:64979)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.589573221Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"io task","client":"0","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1712025-01-27T19:38:40.995Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.590166252Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"2","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1722025-01-27T19:38:40.995Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.590229362Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"0","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1732025-01-27T19:38:40.995Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.590268252Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"1","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1742025-01-27T19:38:40.995Z{"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-27T19:38:39.590910553Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"1","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1752025-01-27T19:38:40.995Z{"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-27T19:38:39.590947103Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"2","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1762025-01-27T19:38:40.995Z{"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-27T19:38:39.590963673Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"0","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1772025-01-27T19:38:40.998Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591345784Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1782025-01-27T19:38:40.999Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591442254Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1792025-01-27T19:38:40.999Z{"msg":"[0]R flush_numbers: [1494, 1494, 1494, 1494, 1494]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591550874Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1802025-01-27T19:38:40.999Z{"msg":"[0]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591576214Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1812025-01-27T19:38:40.999Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591590334Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1822025-01-27T19:38:40.999Z{"msg":"[1]R flush_numbers: [1494, 1494, 1494, 1494, 1494]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591607964Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1832025-01-27T19:38:40.999Z{"msg":"[1]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591627614Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1842025-01-27T19:38:40.999Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591650104Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1852025-01-27T19:38:40.999Z{"msg":"[2]R flush_numbers: [1494, 1494, 1494, 1494, 1494]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591665304Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1862025-01-27T19:38:40.999ZWait for a query_work_queue command to finish before sending IO
1872025-01-27T19:38:40.999Z{"msg":"[2]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591695435Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1882025-01-27T19:38:40.999Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591709475Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1892025-01-27T19:38:40.999Z{"msg":"Max found gen is 26","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591729715Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1902025-01-27T19:38:40.999Z{"msg":"Generation requested: 31 >= found:26","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591742964Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1912025-01-27T19:38:40.999Z{"msg":"Next flush: 1495","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591767595Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1922025-01-27T19:38:40.999Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591780644Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"":"downstairs","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1932025-01-27T19:38:40.999Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591793404Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1942025-01-27T19:38:40.999Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591805644Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"0","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1952025-01-27T19:38:40.999Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591819745Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"1","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1962025-01-27T19:38:40.999Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591851465Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"client":"2","":"downstairs","session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1972025-01-27T19:38:40.999Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591867635Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1982025-01-27T19:38:40.999Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591898225Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
1992025-01-27T19:38:40.999Z{"msg":"571e0e0a-c0dd-403f-8fe3-f02b0e092199 is now active with session: b59e9705-d8cc-4289-9643-18bef427d280","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591923405Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
2002025-01-27T19:38:40.999Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591953785Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223,"session_id":"b59e9705-d8cc-4289-9643-18bef427d280"}
2012025-01-27T19:38:40.999Z{"msg":"The guest has finished waiting for activation with:31","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:39.591967785Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223}
2022025-01-27T19:38:40.999ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2032025-01-27T19:38:40.999ZFill test
2042025-01-27T19:38:41.002ZRead and Verify all blocks (0..50 range:false)
2052025-01-27T19:38:41.007ZWrote out file "/var/tmp/test_up-build/verify_file"
2062025-01-27T19:38:41.007ZCLIENT: Tests done. All submitted work has been ACK'd
2072025-01-27T19:38:41.009Z----------------------------------------------------------------
2082025-01-27T19:38:41.009Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:1
2092025-01-27T19:38:41.009ZStates: Active Active Active
2102025-01-27T19:38:41.009ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2112025-01-27T19:38:41.009Z 1002 Acked Read 50 Done Done Done false
2122025-01-27T19:38:41.010Z STATES DS:0 DS:1 DS:2 TOTAL
2132025-01-27T19:38:41.010Z Sent 0 0 0 0
2142025-01-27T19:38:41.010Z Done 1 1 1 3
2152025-01-27T19:38:41.010Z Skipped 0 0 0 0
2162025-01-27T19:38:41.010Z Error 0 0 0 0
2172025-01-27T19:38:41.010ZLast Flush: 1001 1001 1001
2182025-01-27T19:38:41.010ZDownstairs last five completed: 1001 1000
2192025-01-27T19:38:41.010ZUpstairs last five completed: 1002 1001 1000
2202025-01-27T19:38:41.010ZCLIENT: Up:0 ds:1 act:3
2212025-01-27T19:38:45.009Z----------------------------------------------------------------
2222025-01-27T19:38:45.009Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:0
2232025-01-27T19:38:45.009ZDownstairs last five completed: 1003 1002 1001 1000
2242025-01-27T19:38:45.009ZUpstairs last five completed: 1003 1002 1001 1000
2252025-01-27T19:38:45.009ZCLIENT: Up:0 ds:0 act:3
2262025-01-27T19:38:45.009ZCLIENT: All crucible jobs finished, exiting program
2272025-01-27T19:38:45.012Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-01-27T19:38:43.605881336Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1223}
2282025-01-27T19:38:45.019ZRepair setup passed
2292025-01-27T19:38:45.023ZCopy the region for /var/tmp/test_up-build/8830
2302025-01-27T19:38:45.026Zcp -r /var/tmp/test_up-build/8830 /var/tmp/test_up-build/previous
2312025-01-27T19:38:45.028Z/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
2322025-01-27T19:38:45.085Z{"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-27T19:38:43.681761378Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"task":"crutest"}
2332025-01-27T19:38:45.088Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.682278479Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"task":"crutest"}
2342025-01-27T19:38:45.088Z{"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-27T19:38:43.683892361Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"task":"crutest"}
2352025-01-27T19:38:45.088Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.684072582Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229}
2362025-01-27T19:38:45.088Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"d77aa90b6afe7d7ddb1dc63211fa4216c8866a90\",\n git_commit_timestamp: \"2025-01-27T19:20:16.000000000Z\",\n git_branch: \"mkeeter/shrink-replay-buffer\",\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-27T19:38:43.684124242Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229}
2372025-01-27T19:38:45.088Z{"msg":"Upstairs <-> Downstairs Message Version: 12","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.684151042Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229}
2382025-01-27T19:38:45.088Z{"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-27T19:38:43.684169372Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229}
2392025-01-27T19:38:45.088Z{"msg":"Crucible 2c74206b-2d0e-49ef-a256-8bd973cb86b4 has session id: 09c5ad51-d392-4751-9d12-1dd2d6377b8e","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.684684523Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2402025-01-27T19:38:45.088Z{"msg":"Upstairs opts: Upstairs UUID: 2c74206b-2d0e-49ef-a256-8bd973cb86b4, 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-27T19:38:43.684730093Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2412025-01-27T19:38:45.088Z{"msg":"Crucible stats registered with UUID: 2c74206b-2d0e-49ef-a256-8bd973cb86b4","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.684839783Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2422025-01-27T19:38:45.088Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-01-27T19:38:43.684854893Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2432025-01-27T19:38:45.092Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.685559024Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"task":"crutest"}
2442025-01-27T19:38:45.092Z{"msg":"The guest has requested activation with gen:32","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.685615574Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229}
2452025-01-27T19:38:45.092Z{"msg":"2c74206b-2d0e-49ef-a256-8bd973cb86b4 active request set","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.685695224Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2462025-01-27T19:38:45.092Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.685722674Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"0","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2472025-01-27T19:38:45.092Z{"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-27T19:38:43.685749984Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"0","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2482025-01-27T19:38:45.092Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.685775234Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"1","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2492025-01-27T19:38:45.092Z{"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-27T19:38:43.685791064Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"1","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2502025-01-27T19:38:45.092Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.685804474Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"2","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2512025-01-27T19:38:45.092Z{"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-27T19:38:43.685818964Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"2","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2522025-01-27T19:38:45.092Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.685840664Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"io task","client":"2","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2532025-01-27T19:38:45.092Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.685855084Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"io task","client":"0","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2542025-01-27T19:38:45.092Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.685868815Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"io task","client":"1","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2552025-01-27T19:38:45.092Z{"msg":"ds_connection connected from Ok(127.0.0.1:65496)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.686037885Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"io task","client":"0","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2562025-01-27T19:38:45.092Z{"msg":"ds_connection connected from Ok(127.0.0.1:54314)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.686081005Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"io task","client":"2","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2572025-01-27T19:38:45.092Z{"msg":"ds_connection connected from Ok(127.0.0.1:37530)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.686110365Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"io task","client":"1","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2582025-01-27T19:38:45.092Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.686778316Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"0","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2592025-01-27T19:38:45.092Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.686817566Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"2","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2602025-01-27T19:38:45.092Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.686880486Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"1","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2612025-01-27T19:38:45.092Z{"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-27T19:38:43.687372117Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"1","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2622025-01-27T19:38:45.092Z{"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-27T19:38:43.687487467Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"0","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2632025-01-27T19:38:45.092Z{"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-27T19:38:43.687515527Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"2","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2642025-01-27T19:38:45.092Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.687725197Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2652025-01-27T19:38:45.092Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.687844277Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2662025-01-27T19:38:45.092Z{"msg":"[0]R flush_numbers: [1495, 1495, 1495, 1495, 1495]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.687957238Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2672025-01-27T19:38:45.092Z{"msg":"[0]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.687982907Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2682025-01-27T19:38:45.092Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.687997398Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2692025-01-27T19:38:45.092Z{"msg":"[1]R flush_numbers: [1495, 1495, 1495, 1495, 1495]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688011258Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2702025-01-27T19:38:45.092Z{"msg":"[1]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688037228Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2712025-01-27T19:38:45.092Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688058108Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2722025-01-27T19:38:45.092Z{"msg":"[2]R flush_numbers: [1495, 1495, 1495, 1495, 1495]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688073378Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2732025-01-27T19:38:45.092Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688093548Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2742025-01-27T19:38:45.092Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688115698Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2752025-01-27T19:38:45.092ZWait for a query_work_queue command to finish before sending IO
2762025-01-27T19:38:45.092Z{"msg":"Max found gen is 32","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688154468Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2772025-01-27T19:38:45.093Z{"msg":"Generation requested: 32 >= found:32","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688185858Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2782025-01-27T19:38:45.093Z{"msg":"Next flush: 1496","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688217968Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2792025-01-27T19:38:45.093Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688251338Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"":"downstairs","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2802025-01-27T19:38:45.093Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688276188Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2812025-01-27T19:38:45.093Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688308348Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"0","":"downstairs","session_id":"Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2822025-01-27T19:38:45.093Z09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2832025-01-27T19:38:45.093Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688346618Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"1","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2842025-01-27T19:38:45.093Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688379398Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"client":"2","":"downstairs","session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2852025-01-27T19:38:45.096Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688394698Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2862025-01-27T19:38:45.096Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688413958Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2872025-01-27T19:38:45.096Z{"msg":"2c74206b-2d0e-49ef-a256-8bd973cb86b4 is now active with session: 09c5ad51-d392-4751-9d12-1dd2d6377b8e","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688426988Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2882025-01-27T19:38:45.096Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688438668Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229,"session_id":"09c5ad51-d392-4751-9d12-1dd2d6377b8e"}
2892025-01-27T19:38:45.096Z{"msg":"The guest has finished waiting for activation with:32","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:43.688457018Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229}
2902025-01-27T19:38:45.096ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
2912025-01-27T19:38:45.096ZFill test
2922025-01-27T19:38:45.099ZRead and Verify all blocks (0..50 range:false)
2932025-01-27T19:38:45.102ZWrote out file "/var/tmp/test_up-build/verify_file"
2942025-01-27T19:38:45.102ZCLIENT: Tests done. All submitted work has been ACK'd
2952025-01-27T19:38:45.105Z----------------------------------------------------------------
2962025-01-27T19:38:45.105Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:1
2972025-01-27T19:38:45.105ZStates: Active Active Active
2982025-01-27T19:38:45.105ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2992025-01-27T19:38:45.105Z 1002 Acked Read 50 Done Done Done false
3002025-01-27T19:38:45.105Z STATES DS:0 DS:1 DS:2 TOTAL
3012025-01-27T19:38:45.105Z Sent 0 0 0 0
3022025-01-27T19:38:45.105Z Done 1 1 1 3
3032025-01-27T19:38:45.105Z Skipped 0 0 0 0
3042025-01-27T19:38:45.105Z Error 0 0 0 0
3052025-01-27T19:38:45.105ZLast Flush: 1001 1001 1001
3062025-01-27T19:38:45.105ZDownstairs last five completed: 1001 1000
3072025-01-27T19:38:45.105ZUpstairs last five completed: 1002 1001 1000
3082025-01-27T19:38:45.105ZCLIENT: Up:0 ds:1 act:3
3092025-01-27T19:38:49.105Z----------------------------------------------------------------
3102025-01-27T19:38:49.105Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:0
3112025-01-27T19:38:49.105ZDownstairs last five completed: 1003 1002 1001 1000
3122025-01-27T19:38:49.105ZUpstairs last five completed: 1003 1002 1001 1000
3132025-01-27T19:38:49.108ZCLIENT: Up:0 ds:0 act:3
3142025-01-27T19:38:49.108ZCLIENT: All crucible jobs finished, exiting program
3152025-01-27T19:38:49.108Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-01-27T19:38:47.701071969Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1229}
3162025-01-27T19:38:49.111ZRepair part 1 passed
3172025-01-27T19:38:49.113Z
3182025-01-27T19:38:49.113ZKill the current downstairs
3192025-01-27T19:38:49.277ZDownstairs 2 stopped
3202025-01-27T19:38:49.277Zmv /var/tmp/test_up-build/8830 /var/tmp/test_up-build/new
3212025-01-27T19:38:49.280ZNow put back the original so we have a mismatch
3222025-01-27T19:38:49.280Zmv /var/tmp/test_up-build/previous /var/tmp/test_up-build/8830
3232025-01-27T19:38:49.282ZRestart downstairs with old directory
3242025-01-27T19:38:49.333Z/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
3252025-01-27T19:38:49.349ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
3262025-01-27T19:38:49.354Z 0 000-009 32 32 31 1496 1496 1495 F F F <---
3272025-01-27T19:38:49.354Z 1 010-019 32 32 31 1496 1496 1495 F F F <---
3282025-01-27T19:38:49.354Z 2 020-029 32 32 31 1496 1496 1495 F F F <---
3292025-01-27T19:38:49.354Z 3 030-039 32 32 31 1496 1496 1495 F F F <---
3302025-01-27T19:38:49.354Z 4 040-049 32 32 31 1496 1496 1495 F F F <---
3312025-01-27T19:38:49.355ZMax gen: 32, Max flush: 1496
3322025-01-27T19:38:49.556ZError: Difference in extent metadata found!
3332025-01-27T19:38:49.556Z
3342025-01-27T19:38:49.556ZStack backtrace:
3352025-01-27T19:38:49.556Z 0: anyhow::error::<impl anyhow::Error>::msg
3362025-01-27T19:38:49.556Z at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.92/src/backtrace.rs:27:14
3372025-01-27T19:38:49.556Z 1: anyhow::__private::format_err
3382025-01-27T19:38:49.557Z at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.92/src/lib.rs:691:13
3392025-01-27T19:38:49.572Zdump test found error as expected
3402025-01-27T19:38:49.575Z
3412025-01-27T19:38:49.575Z
3422025-01-27T19:38:49.575Z/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
3432025-01-27T19:38:49.630Z{"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-27T19:38:48.226166203Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"task":"crutest"}
3442025-01-27T19:38:49.633Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.226685643Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"task":"crutest"}
3452025-01-27T19:38:49.633Z{"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-27T19:38:48.228350826Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"task":"crutest"}
3462025-01-27T19:38:49.633Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.228586886Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237}
3472025-01-27T19:38:49.633Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"d77aa90b6afe7d7ddb1dc63211fa4216c8866a90\",\n git_commit_timestamp: \"2025-01-27T19:20:16.000000000Z\",\n git_branch: \"mkeeter/shrink-replay-buffer\",\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-27T19:38:48.228628966Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237}
3482025-01-27T19:38:49.633Z{"msg":"Upstairs <-> Downstairs Message Version: 12","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.228650816Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237}
3492025-01-27T19:38:49.633Z{"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-27T19:38:48.228665837Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237}
3502025-01-27T19:38:49.633Z{"msg":"Crucible f4080dfd-b868-4133-86cc-124c8ff7140e has session id: 74168230-9f0c-4967-865a-4e31a4dfee4c","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.229182207Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3512025-01-27T19:38:49.633Z{"msg":"Upstairs opts: Upstairs UUID: f4080dfd-b868-4133-86cc-124c8ff7140e, 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-27T19:38:48.229277137Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3522025-01-27T19:38:49.633Z{"msg":"Crucible stats registered with UUID: f4080dfd-b868-4133-86cc-124c8ff7140e","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.229313387Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3532025-01-27T19:38:49.633Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-01-27T19:38:48.229327627Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3542025-01-27T19:38:49.636Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230198629Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"task":"crutest"}
3552025-01-27T19:38:49.636Z{"msg":"The guest has requested activation with gen:33","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230283559Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237}
3562025-01-27T19:38:49.636Z{"msg":"f4080dfd-b868-4133-86cc-124c8ff7140e active request set","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230319769Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3572025-01-27T19:38:49.636Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230337309Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"0","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3582025-01-27T19:38:49.636Z{"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-27T19:38:48.230372639Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"0","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3592025-01-27T19:38:49.636Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230390519Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"1","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3602025-01-27T19:38:49.636Z{"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-27T19:38:48.230442819Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"1","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3612025-01-27T19:38:49.636Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230463069Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3622025-01-27T19:38:49.636Z{"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-27T19:38:48.230494449Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3632025-01-27T19:38:49.636Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230509419Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3642025-01-27T19:38:49.636Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230541509Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"0","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3652025-01-27T19:38:49.636Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230617769Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"1","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3662025-01-27T19:38:49.636Z{"msg":"ds_connection connected from Ok(127.0.0.1:33739)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.230670419Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"0","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3672025-01-27T19:38:49.636Z{"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-27T19:38:48.230803429Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3682025-01-27T19:38:49.637Z{"msg":"ds_connection connected from Ok(127.0.0.1:34973)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.23084137Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"1","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3692025-01-27T19:38:49.637Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2025-01-27T19:38:48.23089721Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3702025-01-27T19:38:49.637Z{"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-27T19:38:48.23094137Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3712025-01-27T19:38:49.637Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.23096387Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3722025-01-27T19:38:49.637Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.23117397Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"1","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3732025-01-27T19:38:49.637Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.23120881Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"0","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3742025-01-27T19:38:49.637Z{"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-27T19:38:48.231759721Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"0","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3752025-01-27T19:38:49.637Z{"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-27T19:38:48.231913281Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"1","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3762025-01-27T19:38:49.637Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.232115002Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3772025-01-27T19:38:49.637Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:48.232235142Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3782025-01-27T19:38:59.636Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.231893134Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3792025-01-27T19:38:59.636Z{"msg":"ds_connection connected from Ok(127.0.0.1:37030)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.232126595Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"io task","client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3802025-01-27T19:38:59.641Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.233275146Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3812025-01-27T19:38:59.641Z{"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-27T19:38:58.233799207Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3822025-01-27T19:38:59.641Z{"msg":"[0]R flush_numbers: [1496, 1496, 1496, 1496, 1496]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234182888Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3832025-01-27T19:38:59.641Z{"msg":"[0]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234216038Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3842025-01-27T19:38:59.641Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234232008Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3852025-01-27T19:38:59.641Z{"msg":"[1]R flush_numbers: [1496, 1496, 1496, 1496, 1496]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234245428Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3862025-01-27T19:38:59.641Z{"msg":"[1]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234268018Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3872025-01-27T19:38:59.641Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234290298Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3882025-01-27T19:38:59.642Z{"msg":"[2]R flush_numbers: [1495, 1495, 1495, 1495, 1495]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234304098Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3892025-01-27T19:38:59.642Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234325618Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3902025-01-27T19:38:59.642Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234339328Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3912025-01-27T19:38:59.642Z{"msg":"Max found gen is 33","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234359178Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3922025-01-27T19:38:59.642Z{"msg":"Generation requested: 33 >= found:33","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234372238Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3932025-01-27T19:38:59.642Z{"msg":"Next flush: 1497","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234392288Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3942025-01-27T19:38:59.642Z{"msg":"extent 0 needs reconciliation: ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 31, flush: 1495, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234407748Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3952025-01-27T19:38:59.642Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 31, flush: 1495, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234430848Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3962025-01-27T19:38:59.642Z{"msg":"found dest for source 0 for extent at index 0 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234445348Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3972025-01-27T19:38:59.642Z{"msg":"extent 1 needs reconciliation: ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 31, flush: 1495, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234467808Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3982025-01-27T19:38:59.642Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 31, flush: 1495, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234483898Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
3992025-01-27T19:38:59.642Z{"msg":"found dest for source 0 for extent at index 1 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234504328Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4002025-01-27T19:38:59.642Z{"msg":"extent 2 needs reconciliation: ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 31, flush: 1495, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234519708Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4012025-01-27T19:38:59.642Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 31, flush: 1495, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234535238Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4022025-01-27T19:38:59.642Z{"msg":"found dest for source 0 for extent at index 2 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234548828Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4032025-01-27T19:38:59.642Z{"msg":"extent 3 needs reconciliation: ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 31, flush: 1495, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234570718Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4042025-01-27T19:38:59.642Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 31, flush: 1495, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234585908Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4052025-01-27T19:38:59.642Z{"msg":"found dest for source 0 for extent at index 3 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234607198Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4062025-01-27T19:38:59.642Z{"msg":"extent 4 needs reconciliation: ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 32, flush: 1496, dirty: false } ExtentMetadata { gen: 31, flush: 1495, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234622448Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4072025-01-27T19:38:59.642Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 32, flush: 1496, dirty: false }, ExtentMetadata { gen: 31, flush: 1495, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234647348Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4082025-01-27T19:38:59.642Z{"msg":"found dest for source 0 for extent at index 4 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234661808Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"mend","":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4092025-01-27T19:38:59.642Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234694448Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"0","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4102025-01-27T19:38:59.642Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234733619Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"1","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4112025-01-27T19:38:59.642Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234775199Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4122025-01-27T19:38:59.642Z{"msg":"Full repair list: {ExtentId(4): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(1): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(0): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(2): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(3): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }}","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234820529Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4132025-01-27T19:38:59.642Z{"msg":"Task list: [ReconcileIO { id: ReconciliationId(0), op: ExtentFlush { repair_id: ReconciliationId(0), extent_id: ExtentId(4), client_id: ClientId(0), flush_number: 1497, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(1), op: ExtentClose { repair_id: ReconciliationId(1), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(2), op: ExtentRepair { repair_id: ReconciliationId(2), 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(3), op: ExtentReopen { repair_id: ReconciliationId(3), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(4), op: ExtentFlush { repair_id: ReconciliationId(4), extent_id: ExtentId(1), client_id: ClientId(0), flush_number: 1497, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(5), op: ExtentClose { repair_id: ReconciliationId(5), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(6), op: ExtentRepair { repair_id: ReconciliationId(6), 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(7), op: ExtentReopen { repair_id: ReconciliationId(7), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(8), op: ExtentFlush { repair_id: ReconciliationId(8), extent_id: ExtentId(0), client_id: ClientId(0), flush_number: 1497, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(9), op: ExtentClose { repair_id: ReconciliationId(9), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(10), op: ExtentRepair { repair_id: ReconciliationId(10), extent_id: ExtentId(0), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(11), op: ExtentReopen { repair_id: ReconciliationId(11), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(12), op: ExtentFlush { repair_id: ReconciliationId(12), extent_id: ExtentId(2), client_id: ClientId(0), flush_number: 1497, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(13), op: ExtentClose { repair_id: ReconciliationId(13), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(14), op: ExtentRepair { repair_id: ReconciliationId(14), 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(15), op: ExtentReopen { repair_id: ReconciliationId(15), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(16), op: ExtentFlush { repair_id: ReconciliationId(16), extent_id: ExtentId(3), client_id: ClientId(0), flush_number: 1497, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(17), op: ExtentClose { repair_id: ReconciliationId(17), extent_id: ExtentId(3) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(18), op: ExtentRepair { repair_id: ReconciliationId(18), extent_id: ExtentId(3), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(19), op: ExtentReopen { repair_id: ReconciliationId(19), extent_id: ExtentId(3) }, state: ClientData([New, New, New]) }]","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234933119Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4142025-01-27T19:38:59.642Z{"msg":"starting reconciliation 82ce1b35-be3a-4dbb-9f57-fc4ed7aa3224: found 20 extents that need repair","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.234961689Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4152025-01-27T19:38:59.642Z{"msg":"sending reconcile request ReconciliationId(2)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.235272159Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4162025-01-27T19:38:59.649Z{"msg":"sending reconcile request ReconciliationId(6)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.245299654Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4172025-01-27T19:38:59.653Z{"msg":"sending reconcile request ReconciliationId(10)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.24920077Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4182025-01-27T19:38:59.656Z{"msg":"sending reconcile request ReconciliationId(14)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.252691875Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4192025-01-27T19:38:59.660Z{"msg":"sending reconcile request ReconciliationId(18)","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.25617153Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4202025-01-27T19:38:59.664Z{"msg":"done with reconciliation","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.259357865Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"":"downstairs","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4212025-01-27T19:38:59.664Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.259394465Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"0","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4222025-01-27T19:38:59.664Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.259409985Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"1","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4232025-01-27T19:38:59.665Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.259424465Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"client":"2","":"downstairs","session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4242025-01-27T19:38:59.665Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.259455095Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4252025-01-27T19:38:59.665Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO
4262025-01-27T19:38:59.665Z,"time":"2025-01-27T19:38:58.259469925Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4272025-01-27T19:38:59.665Z{"msg":"f4080dfd-b868-4133-86cc-124c8ff7140e is now active with session: 74168230-9f0c-4967-865a-4e31a4dfee4c","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.259488405Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237,"session_id":"74168230-9f0c-4967-865a-4e31a4dfee4c"}
4282025-01-27T19:38:59.665Z{"msg":"The guest has finished waiting for activation with:33","v":0,"name":"crucible","level":30,"time":"2025-01-27T19:38:58.259551455Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237}
4292025-01-27T19:38:59.667ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
4302025-01-27T19:38:59.667ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
4312025-01-27T19:38:59.667ZRead and Verify all blocks (0..50 range:true)
4322025-01-27T19:38:59.670ZWrote out file "/var/tmp/test_up-build/verify_file"
4332025-01-27T19:38:59.670ZVerify test completed
4342025-01-27T19:38:59.670ZWrote out file "/var/tmp/test_up-build/verify_file"
4352025-01-27T19:38:59.670ZCLIENT: Tests done. All submitted work has been ACK'd
4362025-01-27T19:38:59.675Z----------------------------------------------------------------
4372025-01-27T19:38:59.676Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:1
4382025-01-27T19:38:59.676ZStates: Active Active Active
4392025-01-27T19:38:59.676ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
4402025-01-27T19:38:59.676Z 1000 Acked Read 50 Done Done Done false
4412025-01-27T19:38:59.676Z STATES DS:0 DS:1 DS:2 TOTAL
4422025-01-27T19:38:59.676Z Sent 0 0 0 0
4432025-01-27T19:38:59.676Z Done 1 1 1 3
4442025-01-27T19:38:59.676Z Skipped 0 0 0 0
4452025-01-27T19:38:59.676Z Error 0 0 0 0
4462025-01-27T19:38:59.676ZLast Flush: 0 0 0
4472025-01-27T19:38:59.676ZDownstairs last five completed:
4482025-01-27T19:38:59.676ZUpstairs last five completed: 1000
4492025-01-27T19:38:59.676ZCLIENT: Up:0 ds:1 act:3
4502025-01-27T19:39:03.672Z----------------------------------------------------------------
4512025-01-27T19:39:03.672Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:0
4522025-01-27T19:39:03.672ZDownstairs last five completed: 1001 1000
4532025-01-27T19:39:03.672ZUpstairs last five completed: 1001 1000
4542025-01-27T19:39:03.675ZCLIENT: Up:0 ds:0 act:3
4552025-01-27T19:39:03.675ZCLIENT: All crucible jobs finished, exiting program
4562025-01-27T19:39:03.675Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-01-27T19:39:02.268199869Z","hostname":"w-01JJMM54SE509ZXJB5G5B3AP3X","pid":1237}
4572025-01-27T19:39:03.680ZRepair part 2 passed
4582025-01-27T19:39:03.684Z/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-01-27T19:39:03.696ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
4602025-01-27T19:39:03.696Z 0 000-009 32 32 32 1496 1496 1496 F F F
4612025-01-27T19:39:03.696Z 1 010-019 32 32 32 1496 1496 1496 F F F
4622025-01-27T19:39:03.696Z 2 020-029 32 32 32 1496 1496 1496 F F F
4632025-01-27T19:39:03.702Z 3 030-039 32 32 32 1496 1496 1496 F F F
4642025-01-27T19:39:03.703Z 4 040-049 32 32 32 1496 1496 1496 F F F
4652025-01-27T19:39:03.703ZMax gen: 32, Max flush: 1496
4662025-01-27T19:39:03.703Zdump test passed
4672025-01-27T19:39:03.703Z/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-01-27T19:39:03.717Z Extent 1
4692025-01-27T19:39:03.726ZGEN 32 32 32
4702025-01-27T19:39:03.726ZFLUSH_ID 1496 1496 1496
4712025-01-27T19:39:03.726ZDIRTY
4722025-01-27T19:39:03.726Z
4732025-01-27T19:39:03.726ZBLOCK D0 D1 D2 C0 C1 C2 DIFF
4742025-01-27T19:39:03.726Z010 A A A A A A
4752025-01-27T19:39:03.726Z011 A A A A A A
4762025-01-27T19:39:03.726Z012 A A A A A A
4772025-01-27T19:39:03.726Z013 A A A A A A
4782025-01-27T19:39:03.726Z014 A A A A A A
4792025-01-27T19:39:03.727Z015 A A A A A A
4802025-01-27T19:39:03.735Z016 A A A A A A
4812025-01-27T19:39:03.735Z017 A A A A A A
4822025-01-27T19:39:03.735Z018 A A A A A A
4832025-01-27T19:39:03.735Z019 A A A A A A
4842025-01-27T19:39:03.735Zdump extent test passed
4852025-01-27T19:39:03.735Z/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-01-27T19:39:03.747ZExtent 2 Block in extent 0 Actual block 20
4872025-01-27T19:39:03.747Z
4882025-01-27T19:39:03.757Z DATA SHA256 VER
4892025-01-27T19:39:03.757Z------ ---------------------------------------------------------------- ---
4902025-01-27T19:39:03.757Z 0 ad3d0e88276af7eb1f904413516e1a8c1f9c2fa8b17b86b2d842d08303e90aa2 A
4912025-01-27T19:39:03.757Z 1 ad3d0e88276af7eb1f904413516e1a8c1f9c2fa8b17b86b2d842d08303e90aa2 A
4922025-01-27T19:39:03.757Z 2 ad3d0e88276af7eb1f904413516e1a8c1f9c2fa8b17b86b2d842d08303e90aa2 A
4932025-01-27T19:39:03.757Z
4942025-01-27T19:39:03.757ZNONCES 0 1 2 DIFF
4952025-01-27T19:39:03.757Z------ ------------------------ ------------------------ ------------------------ -----
4962025-01-27T19:39:03.757Z
4972025-01-27T19:39:03.757Z TAGS 0 1 2 DIFF
4982025-01-27T19:39:03.757Z------ -------------------------------- -------------------------------- -------------------------------- -----
4992025-01-27T19:39:03.758Z
5002025-01-27T19:39:03.758ZHASHES 0 1 2 DIFF
5012025-01-27T19:39:03.758Z------ ---------------- ---------------- ---------------- -----
5022025-01-27T19:39:03.758Z 0 42916ab6fa364c70 42916ab6fa364c70 42916ab6fa364c70
5032025-01-27T19:39:03.758Z
5042025-01-27T19:39:03.758Zdump block test passed
5052025-01-27T19:39:03.758ZInitial upstairs tests have completed, stopping all downstairs
5062025-01-27T19:39:08.816ZCreating 4 larger downstairs regions
5072025-01-27T19:39:08.923ZStarting 4 downstairs
5082025-01-27T19:39:13.929Zdsc restarted at PID: 1250
5092025-01-27T19:39:14.151ZNow do the replace-reconcile test
5102025-01-27T19:39:14.203ZUsing 8840 for the replacement port
5112025-01-27T19:41:47.532ZCompleted test: replace-reconcile
5122025-01-27T19:41:47.534ZNow do the replace-before-active test
5132025-01-27T19:44:32.141ZCompleted test: replace-before-active
5142025-01-27T19:44:32.144ZAll tests have completed, stopping all downstairs
5152025-01-27T19:44:32.200Z
5162025-01-27T19:44:32.200ZAll Tests have passed
5172025-01-27T19:44:32.203Z7:49 Test duration
5182025-01-27T19:44:32.203Z
5192025-01-27T19:44:32.203Zreal 7:49.676357112
5202025-01-27T19:44:32.203Zuser 1:02.640219030
5212025-01-27T19:44:32.203Zsys 9.884906157
5222025-01-27T19:44:32.203Ztrap 0.079724574
5232025-01-27T19:44:32.203Ztflt 0.015558923
5242025-01-27T19:44:32.203Zdflt 0.014228943
5252025-01-27T19:44:32.203Zkflt 0.001140472
5262025-01-27T19:44:32.203Zlock 5:42:45.815423256
5272025-01-27T19:44:32.203Zslp 24:31.875381467
5282025-01-27T19:44:32.203Zlat 7.441461857
5292025-01-27T19:44:32.203Zstop 0.129994206
5302025-01-27T19:44:32.203Z+ echo 'test-up-unencrypted ends'
5312025-01-27T19:44:32.203Ztest-up-unencrypted ends
5322025-01-27T19:44:37.207Zprocess exited: duration 477880 ms, exit code 0
5332025-01-27T19:44:37.208Zexec warning: : stdio descriptors remain open after task exit; waiting 60 seconds for them to close
5342025-01-27T19:45:37.211Zexec warning: : stdout descriptor may be held open by a background process; giving up!
5352025-01-27T19:45:37.211Zexec warning: : stderr descriptor may be held open by a background process; giving up!
 
5362025-01-27T19:45:37.223Zfound 14 output files
5372025-01-27T19:45:37.223Zuploading: /tmp/test_up-build/dsc-out.txt (37449 bytes)
5382025-01-27T19:45:38.235Zuploaded: /tmp/test_up-build/dsc-out.txt
5392025-01-27T19:45:38.235Zuploading: /tmp/test_up-build/test_up_out.txt (7963433 bytes)
5402025-01-27T19:45:39.383Zuploaded: /tmp/test_up-build/test_up_out.txt
5412025-01-27T19:45:39.383Zuploading: /tmp/test_up-build/dsc/downstairs-8810.txt (2504 bytes)
5422025-01-27T19:45:40.391Zuploaded: /tmp/test_up-build/dsc/downstairs-8810.txt
5432025-01-27T19:45:40.391Zuploading: /tmp/test_up-build/dsc/downstairs-8820.txt (144626 bytes)
5442025-01-27T19:45:41.414Zuploaded: /tmp/test_up-build/dsc/downstairs-8820.txt
5452025-01-27T19:45:41.417Zuploading: /tmp/test_up-build/dsc/downstairs-8830.txt (251030 bytes)
5462025-01-27T19:45:42.442Zuploaded: /tmp/test_up-build/dsc/downstairs-8830.txt
5472025-01-27T19:45:42.442Zuploading: /tmp/test_up-build/dsc/downstairs-8840.txt (139440 bytes)
5482025-01-27T19:45:43.464Zuploaded: /tmp/test_up-build/dsc/downstairs-8840.txt
5492025-01-27T19:45:43.466Zuploading: /tmp/debug/df.txt (1270 bytes)
5502025-01-27T19:45:44.473Zuploaded: /tmp/debug/df.txt
5512025-01-27T19:45:44.473Zuploading: /tmp/debug/dtrace.txt (388391 bytes)
5522025-01-27T19:45:44.506Zupload warning: file "/tmp/debug/dtrace.txt" changed size mid upload: 388391 -> 471140
5532025-01-27T19:45:45.514Zuploaded: /tmp/debug/dtrace.txt
5542025-01-27T19:45:45.514Zuploading: /tmp/debug/iostat.txt (160510 bytes)
5552025-01-27T19:45:45.535Zupload warning: file "/tmp/debug/iostat.txt" changed size mid upload: 160510 -> 163210
5562025-01-27T19:45:46.541Zuploaded: /tmp/debug/iostat.txt
5572025-01-27T19:45:46.544Zuploading: /tmp/debug/mpstat.txt (390025 bytes)
5582025-01-27T19:45:46.572Zupload warning: file "/tmp/debug/mpstat.txt" changed size mid upload: 390025 -> 397315
5592025-01-27T19:45:47.579Zuploaded: /tmp/debug/mpstat.txt
5602025-01-27T19:45:47.581Zuploading: /tmp/debug/paging.txt (70057 bytes)
5612025-01-27T19:45:47.593Zupload warning: file "/tmp/debug/paging.txt" changed size mid upload: 70057 -> 71480
5622025-01-27T19:45:48.599Zuploaded: /tmp/debug/paging.txt
5632025-01-27T19:45:48.599Zuploading: /tmp/debug/prstat.txt (732159 bytes)
5642025-01-27T19:45:48.644Zupload warning: file "/tmp/debug/prstat.txt" changed size mid upload: 732159 -> 747708
5652025-01-27T19:45:49.650Zuploaded: /tmp/debug/prstat.txt
5662025-01-27T19:45:49.653Zuploading: /tmp/debug/psrinfo.txt (1528 bytes)
5672025-01-27T19:45:50.660Zuploaded: /tmp/debug/psrinfo.txt
5682025-01-27T19:45:50.660Zuploading: /tmp/debug/upstairs-info.txt (49720 bytes)
5692025-01-27T19:45:51.675Zuploaded: /tmp/debug/upstairs-info.txt