01JPK1XVJ740CZGXETVJ0XFWPT: test-up-encrypted

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

Buildomat Job: 01JPK1YQ4AVZ581Z62YAHVTMAT

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-03-17T22:14:50.078Zjob dependencies complete; ready to run (waiting for 14 m 22 s)
22025-03-17T22:15:42.570Zjob assigned to worker 01JPK2S2SFWTFT81E1XH9PKWDH [factory aws, i-0947086b012d12653] (queued for 52 s)
32025-03-17T22:15:50.742Zdownloading input: /input/build/work/bins/crucible-downstairs.gz
42025-03-17T22:15:53.049Zdownloaded input: /input/build/work/bins/crucible-downstairs.gz
52025-03-17T22:15:53.050Zdownloading input: /input/build/work/bins/crucible-hammer.gz
62025-03-17T22:15:54.968Zdownloaded input: /input/build/work/bins/crucible-hammer.gz
72025-03-17T22:15:54.968Zdownloading input: /input/build/work/bins/crutest.gz
82025-03-17T22:15:56.667Zdownloaded input: /input/build/work/bins/crutest.gz
92025-03-17T22:15:56.667Zdownloading input: /input/build/work/bins/dsc.gz
102025-03-17T22:15:57.558Zdownloaded input: /input/build/work/bins/dsc.gz
112025-03-17T22:15:57.561Zdownloading input: /input/build/work/scripts/perf-downstairs-tick.d
122025-03-17T22:15:57.579Zdownloaded input: /input/build/work/scripts/perf-downstairs-tick.d
132025-03-17T22:15:57.579Zdownloading input: /input/build/work/scripts/test_ds.sh
142025-03-17T22:15:57.596Zdownloaded input: /input/build/work/scripts/test_ds.sh
152025-03-17T22:15:57.596Zdownloading input: /input/build/work/scripts/test_live_repair.sh
162025-03-17T22:15:57.620Zdownloaded input: /input/build/work/scripts/test_live_repair.sh
172025-03-17T22:15:57.620Zdownloading input: /input/build/work/scripts/test_repair.sh
182025-03-17T22:15:57.642Zdownloaded input: /input/build/work/scripts/test_repair.sh
192025-03-17T22:15:57.643Zdownloading input: /input/build/work/scripts/test_replay.sh
202025-03-17T22:15:57.661Zdownloaded input: /input/build/work/scripts/test_replay.sh
212025-03-17T22:15:57.661Zdownloading input: /input/build/work/scripts/test_up.sh
222025-03-17T22:15:57.679Zdownloaded input: /input/build/work/scripts/test_up.sh
232025-03-17T22:15:57.679Zdownloading input: /input/build/work/scripts/upstairs_info.d
242025-03-17T22:15:57.700Zdownloaded input: /input/build/work/scripts/upstairs_info.d
252025-03-17T22:15:57.705Zdownloading input: /input/build/tmp/cargo-test-out.log
262025-03-17T22:15:58.402Zdownloaded input: /input/build/tmp/cargo-test-out.log
 
272025-03-17T22:15:58.402Zstarting task 0: "setup"
282025-03-17T22:15:58.410Z++ uname -s
292025-03-17T22:15:58.413Z+ kern=SunOS
302025-03-17T22:15:58.413Z+ build_user=build
312025-03-17T22:15:58.413Z+ build_uid=12345
322025-03-17T22:15:58.413Z+ work_dir=/work
332025-03-17T22:15:58.413Z+ input_dir=/input
342025-03-17T22:15:58.414Z+ [[ 0 == 12345 ]]
352025-03-17T22:15:58.414Z+ case "$kern" in
362025-03-17T22:15:58.414Z+ groupadd -g 12345 build
372025-03-17T22:15:58.419Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
382025-03-17T22:16:00.423Z+ zfs create -o mountpoint=/work rpool/work
392025-03-17T22:16:00.792Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
402025-03-17T22:16:00.795Z+ home_fs=zfs
412025-03-17T22:16:00.795Z+ [[ zfs == autofs ]]
422025-03-17T22:16:00.795Z+ mkdir -p /home/build
432025-03-17T22:16:00.798Z+ chown build:build /home/build /work
442025-03-17T22:16:02.799Z+ chmod 0700 /home/build /work
452025-03-17T22:16:02.802Zprocess exited: duration 4399 ms, exit code 0
 
462025-03-17T22:16:02.809Zstarting task 1: "authentication"
472025-03-17T22:16:02.827Zprocess exited: duration 17 ms, exit code 0
 
482025-03-17T22:16:02.833Zstarting task 2: "build"
492025-03-17T22:16:02.838Z+ banner cores
502025-03-17T22:16:02.846Z
512025-03-17T22:16:02.846Z #### #### ##### ###### ####
522025-03-17T22:16:02.846Z # # # # # # # #
532025-03-17T22:16:02.846Z # # # # # ##### ####
542025-03-17T22:16:02.846Z # # # ##### # #
552025-03-17T22:16:02.846Z # # # # # # # # #
562025-03-17T22:16:02.846Z #### #### # # ###### ####
572025-03-17T22:16:02.846Z
582025-03-17T22:16:02.846Z+ pfexec coreadm -i /tmp/core.%f.%p -g /tmp/core.%f.%p -e global -e log -e proc-setid -e global-setid
592025-03-17T22:16:02.850Z+ echo 'input bins dir contains:'
602025-03-17T22:16:02.850Zinput bins dir contains:
612025-03-17T22:16:02.850Z+ ls -ltr /input/build/work/bins
622025-03-17T22:16:02.853Ztotal 793815
632025-03-17T22:16:02.853Z-rw-r--r-- 1 root root 118363763 Mar 17 22:15 crucible-downstairs.gz
642025-03-17T22:16:02.853Z-rw-r--r-- 1 root root 106111342 Mar 17 22:15 crucible-hammer.gz
652025-03-17T22:16:02.853Z-rw-r--r-- 1 root root 115364466 Mar 17 22:15 crutest.gz
662025-03-17T22:16:02.853Z-rw-r--r-- 1 root root 66333615 Mar 17 22:15 dsc.gz
672025-03-17T22:16:02.853Z+ banner unpack
682025-03-17T22:16:02.856Z
692025-03-17T22:16:02.856Z # # # # ##### ## #### # #
702025-03-17T22:16:02.856Z # # ## # # # # # # # # #
712025-03-17T22:16:02.856Z # # # # # # # # # # ####
722025-03-17T22:16:02.856Z # # # # # ##### ###### # # #
732025-03-17T22:16:02.856Z # # # ## # # # # # # #
742025-03-17T22:16:02.857Z #### # # # # # #### # #
752025-03-17T22:16:02.857Z
762025-03-17T22:16:02.857Z+ mkdir -p /var/tmp/bins
772025-03-17T22:16:02.857Z+ for t in "$input/bins/"*.gz
782025-03-17T22:16:02.860Z++ basename /input/build/work/bins/crucible-downstairs.gz
792025-03-17T22:16:02.860Z+ b=crucible-downstairs.gz
802025-03-17T22:16:02.860Z+ b=crucible-downstairs
812025-03-17T22:16:02.860Z+ gunzip
822025-03-17T22:16:05.297Z+ chmod +x /var/tmp/bins/crucible-downstairs
832025-03-17T22:16:05.300Z+ for t in "$input/bins/"*.gz
842025-03-17T22:16:05.300Z++ basename /input/build/work/bins/crucible-hammer.gz
852025-03-17T22:16:05.300Z+ b=crucible-hammer.gz
862025-03-17T22:16:05.300Z+ b=crucible-hammer
872025-03-17T22:16:05.300Z+ gunzip
882025-03-17T22:16:07.484Z+ chmod +x /var/tmp/bins/crucible-hammer
892025-03-17T22:16:07.487Z+ for t in "$input/bins/"*.gz
902025-03-17T22:16:07.487Z++ basename /input/build/work/bins/crutest.gz
912025-03-17T22:16:07.490Z+ b=crutest.gz
922025-03-17T22:16:07.490Z+ b=crutest
932025-03-17T22:16:07.490Z+ gunzip
942025-03-17T22:16:09.913Z+ chmod +x /var/tmp/bins/crutest
952025-03-17T22:16:09.918Z+ for t in "$input/bins/"*.gz
962025-03-17T22:16:09.918Z++ basename /input/build/work/bins/dsc.gz
972025-03-17T22:16:09.918Z+ b=dsc.gz
982025-03-17T22:16:09.921Z+ b=dsc
992025-03-17T22:16:09.921Z+ gunzip
1002025-03-17T22:16:11.256Z+ chmod +x /var/tmp/bins/dsc
1012025-03-17T22:16:11.260Z+ export BINDIR=/var/tmp/bins
1022025-03-17T22:16:11.260Z+ BINDIR=/var/tmp/bins
1032025-03-17T22:16:11.260Z+ export RUST_BACKTRACE=1
1042025-03-17T22:16:11.260Z+ RUST_BACKTRACE=1
1052025-03-17T22:16:11.260Z+ jobpid=1147
1062025-03-17T22:16:11.260Z+ echo 'Setup debug logging'
1072025-03-17T22:16:11.260Z+ mkdir /tmp/debug
1082025-03-17T22:16:11.260ZSetup debug logging
1092025-03-17T22:16:11.260Z+ sleep 3600
1102025-03-17T22:16:11.264Z+ psrinfo -v
1112025-03-17T22:16:11.267Z+ df -h
1122025-03-17T22:16:11.274Z+ prstat -d d -mLc 1
1132025-03-17T22:16:11.278Z+ iostat -T d -xn 1
1142025-03-17T22:16:11.278Z+ mpstat -T d 1
1152025-03-17T22:16:11.278Z+ vmstat -T d -p 1
1162025-03-17T22:16:11.278Z+ pfexec dtrace -Z -s /input/build/work/scripts/perf-downstairs-tick.d
1172025-03-17T22:16:11.278Z+ banner test_up_encrypted
1182025-03-17T22:16:11.278Z+ pfexec dtrace -Z -s /input/build/work/scripts/upstairs_info.d
1192025-03-17T22:16:11.281Z
1202025-03-17T22:16:11.282Z ##### ###### #### ##### # # ##### ###### # #
1212025-03-17T22:16:11.282Z # # # # # # # # # ## #
1222025-03-17T22:16:11.282Z # ##### #### # # # # # ##### # # #
1232025-03-17T22:16:11.282Z # # # # # # ##### # # # #
1242025-03-17T22:16:11.282Z # # # # # # # # # # ##
1252025-03-17T22:16:11.282Z # ###### #### # ####### #### # ####### ###### # #
1262025-03-17T22:16:11.282Z
1272025-03-17T22:16:11.282Z+ ptime -m bash /input/build/work/scripts/test_up.sh -N encrypted
1282025-03-17T22:16:11.291Z/input/build/work
1292025-03-17T22:16:11.302ZTurn off color for downstairs dump
1302025-03-17T22:16:11.318ZUpstairs using key: FgdTkwR/arb2Vtm7ywkckbWUQ3+Pwe0qko6mFjLUpg4=
1312025-03-17T22:16:11.321Zdsc output goes to /tmp/test_up-build/dsc-out.txt
1322025-03-17T22:16:11.322ZCreating 3 downstairs regions
1332025-03-17T22:16:11.621ZStarting 3 downstairs
1342025-03-17T22:16:11.624Zdsc started at PID: 1193
1352025-03-17T22:16:16.800ZDisable automatic restart on all downstairs
1362025-03-17T22:16:16.854Z
1372025-03-17T22:16:16.854ZBegin tests, output goes to /tmp/test_up-build/test_up_out.txt
1382025-03-17T22:16:16.858ZRunning test: span
1392025-03-17T22:16:21.003ZCompleted test: span
1402025-03-17T22:16:26.011ZRunning test: big
1412025-03-17T22:16:30.344ZCompleted test: big
1422025-03-17T22:16:35.352ZRunning test: dep
1432025-03-17T22:17:28.102ZCompleted test: dep
1442025-03-17T22:17:33.110ZRunning test: balloon
1452025-03-17T22:18:14.203ZCompleted test: balloon
1462025-03-17T22:18:19.211ZRunning test: deactivate
1472025-03-17T22:19:13.880ZCompleted test: deactivate
1482025-03-17T22:19:18.889ZRunning hammer
1492025-03-17T22:19:36.727ZRun repair tests
1502025-03-17T22:19:36.731Z/var/tmp/bins/crutest fill -g 31 -q --key FgdTkwR/arb2Vtm7ywkckbWUQ3+Pwe0qko6mFjLUpg4= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file
1512025-03-17T22:19:36.788Z{"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-03-17T22:19:35.897270977Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"task":"crutest"}
1522025-03-17T22:19:36.791Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.897826449Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"task":"crutest"}
1532025-03-17T22:19:36.791Z{"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-03-17T22:19:35.899501151Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"task":"crutest"}
1542025-03-17T22:19:36.791Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.899685505Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230}
1552025-03-17T22:19:36.792Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"f72bfdb36aa576722b377a737f26a9b5ef54faf2\",\n git_commit_timestamp: \"2025-03-17T21:58:36.000000000Z\",\n git_branch: \"renovate/tempfile-3.x-lockfile\",\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-03-17T22:19:35.899747573Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230}
1562025-03-17T22:19:36.792Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.899778057Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230}
1572025-03-17T22:19:36.792Z{"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 10, shift: 12 }, extent_count: 5, uuid: 00000000-0000-0000-0000-000000000000, encrypted: true, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.899803262Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230}
1582025-03-17T22:19:36.792Z{"msg":"Crucible 45a3c1a2-f7a5-4305-94aa-c7be99267baa has session id: c00410d8-5d95-4e04-b3b5-75eda230ee1f","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.90037508Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1592025-03-17T22:19:36.792Z{"msg":"Upstairs opts: Upstairs UUID: 45a3c1a2-f7a5-4305-94aa-c7be99267baa, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: true, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.900435589Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1602025-03-17T22:19:36.792Z{"msg":"Crucible stats registered with UUID: 45a3c1a2-f7a5-4305-94aa-c7be99267baa","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.900459364Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1612025-03-17T22:19:36.792Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-03-17T22:19:35.90048089Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1622025-03-17T22:19:36.797Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901491582Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"task":"crutest"}
1632025-03-17T22:19:36.797Z{"msg":"The guest has requested activation with gen:31","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.90155211Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230}
1642025-03-17T22:19:36.797Z{"msg":"45a3c1a2-f7a5-4305-94aa-c7be99267baa active request set","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901595332Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1652025-03-17T22:19:36.797Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901632644Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"0","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1662025-03-17T22:19:36.797Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901693493Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"0","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1672025-03-17T22:19:36.797Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901735694Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"1","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1682025-03-17T22:19:36.797Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901767258Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"1","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1692025-03-17T22:19:36.797Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901792723Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"2","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1702025-03-17T22:19:36.797Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901830256Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"2","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1712025-03-17T22:19:36.797Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901854151Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"io task","client":"2","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1722025-03-17T22:19:36.797Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901890854Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"io task","client":"0","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1732025-03-17T22:19:36.797Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901925767Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"io task","client":"1","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1742025-03-17T22:19:36.797Z{"msg":"ds_connection connected from Ok(127.0.0.1:54239)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901950782Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"io task","client":"0","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1752025-03-17T22:19:36.797Z{"msg":"ds_connection connected from Ok(127.0.0.1:59511)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.901974448Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"io task","client":"2","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1762025-03-17T22:19:36.797Z{"msg":"ds_connection connected from Ok(127.0.0.1:63353)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.902213891Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"io task","client":"1","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1772025-03-17T22:19:36.797Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.90283327Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"2","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1782025-03-17T22:19:36.797Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.902869873Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"1","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1792025-03-17T22:19:36.797Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.902886219Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"0","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1802025-03-17T22:19:36.797Z{"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-03-17T22:19:35.903514376Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"1","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1812025-03-17T22:19:36.797Z{"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-03-17T22:19:35.903558338Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"2","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1822025-03-17T22:19:36.797Z{"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-03-17T22:19:35.903577314Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"0","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1832025-03-17T22:19:36.797Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904001021Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1842025-03-17T22:19:36.797Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904048572Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1852025-03-17T22:19:36.797Z{"msg":"[0]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904076037Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1862025-03-17T22:19:36.797Z{"msg":"[0]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.90411317Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1872025-03-17T22:19:36.797Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904150562Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1882025-03-17T22:19:36.797Z{"msg":"[1]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904185815Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1892025-03-17T22:19:36.797Z{"msg":"[1]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.90421052Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1902025-03-17T22:19:36.797Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904256151Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1912025-03-17T22:19:36.797Z{"msg":"[2]R flush_numbers: [1501, 1501, 1501, 1501, 1501]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904290435Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1922025-03-17T22:19:36.797Z{"msg":"[2]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904334516Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1932025-03-17T22:19:36.797Z{"Wait for a query_work_queue command to finish before sending IO
1942025-03-17T22:19:36.797Zmsg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904380097Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1952025-03-17T22:19:36.797Z{"msg":"Max found gen is 26","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904427868Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1962025-03-17T22:19:36.797Z{"msg":"Generation requested: 31 >= found:26","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.90446828Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1972025-03-17T22:19:36.798Z{"msg":"Next flush: 1502","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904506213Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
1982025-03-17T22:19:36.798Z{"msg":"All extents match","v":0,"name":"crucible","level":30Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
1992025-03-17T22:19:36.798Z,"time":"2025-03-17T22:19:35.904542955Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"":"downstairs","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
2002025-03-17T22:19:36.798Z{Fill test
2012025-03-17T22:19:36.798Z"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904608443Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
2022025-03-17T22:19:36.798Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904635747Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"0","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
2032025-03-17T22:19:36.798Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904652394Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"1","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
2042025-03-17T22:19:36.798Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904678489Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"client":"2","":"downstairs","session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
2052025-03-17T22:19:36.798Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904694486Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
2062025-03-17T22:19:36.798Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904718371Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
2072025-03-17T22:19:36.798Z{"msg":"45a3c1a2-f7a5-4305-94aa-c7be99267baa is now active with session: c00410d8-5d95-4e04-b3b5-75eda230ee1f","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904735038Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
2082025-03-17T22:19:36.798Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904758253Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230,"session_id":"c00410d8-5d95-4e04-b3b5-75eda230ee1f"}
2092025-03-17T22:19:36.798Z{"msg":"The guest has finished waiting for activation with:31","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904792067Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230}
2102025-03-17T22:19:36.798Z{"msg":"Activated sub_volume 45a3c1a2-f7a5-4305-94aa-c7be99267baa","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:35.904813742Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1230}
2112025-03-17T22:19:36.834ZRead and Verify all blocks (0..50 range:false)
2122025-03-17T22:19:36.874ZWrote out file "/var/tmp/test_up-build/verify_file"
2132025-03-17T22:19:36.874ZCLIENT: Tests done. All submitted work has been ACK'd
2142025-03-17T22:19:36.877Z----------------------------------------------------------------
2152025-03-17T22:19:36.877Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:1
2162025-03-17T22:19:36.877ZStates: Active Active Active
2172025-03-17T22:19:36.877ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2182025-03-17T22:19:36.878Z 1002 Acked Read 50 Done Done Done false
2192025-03-17T22:19:36.878Z STATES DS:0 DS:1 DS:2 TOTAL
2202025-03-17T22:19:36.878Z Sent 0 0 0 0
2212025-03-17T22:19:36.878Z Done 1 1 1 3
2222025-03-17T22:19:36.878Z Skipped 0 0 0 0
2232025-03-17T22:19:36.878Z Error 0 0 0 0
2242025-03-17T22:19:36.878ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
2252025-03-17T22:19:36.878ZDownstairs last five completed: 1001 1000
2262025-03-17T22:19:36.878ZUpstairs last five completed: 1002 1001 1000
2272025-03-17T22:19:36.878ZCLIENT: Up:0 ds:1 act:3
2282025-03-17T22:19:40.877Z----------------------------------------------------------------
2292025-03-17T22:19:40.877Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:0
2302025-03-17T22:19:40.877ZDownstairs last five completed: 1003 1002 1001 1000
2312025-03-17T22:19:40.877ZUpstairs last five completed: 1003 1002 1001 1000
2322025-03-17T22:19:40.881ZCLIENT: Up:0 ds:0 act:3
2332025-03-17T22:19:40.881ZCLIENT: All crucible jobs finished, exiting program
2342025-03-17T22:19:40.886ZRepair setup passed
2352025-03-17T22:19:40.890ZCopy the region for /var/tmp/test_up-build/8830
2362025-03-17T22:19:40.893Zcp -r /var/tmp/test_up-build/8830 /var/tmp/test_up-build/previous
2372025-03-17T22:19:40.897Z/var/tmp/bins/crutest fill -g 32 -q --key FgdTkwR/arb2Vtm7ywkckbWUQ3+Pwe0qko6mFjLUpg4= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
2382025-03-17T22:19:40.953Z{"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-03-17T22:19:40.060963454Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"task":"crutest"}
2392025-03-17T22:19:40.956Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.061477683Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"task":"crutest"}
2402025-03-17T22:19:40.956Z{"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-03-17T22:19:40.063147827Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"task":"crutest"}
2412025-03-17T22:19:40.956Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.063333601Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236}
2422025-03-17T22:19:40.956Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"f72bfdb36aa576722b377a737f26a9b5ef54faf2\",\n git_commit_timestamp: \"2025-03-17T21:58:36.000000000Z\",\n git_branch: \"renovate/tempfile-3.x-lockfile\",\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-03-17T22:19:40.063379112Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236}
2432025-03-17T22:19:40.956Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.063402377Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236}
2442025-03-17T22:19:40.956Z{"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 10, shift: 12 }, extent_count: 5, uuid: 00000000-0000-0000-0000-000000000000, encrypted: true, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.063417604Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236}
2452025-03-17T22:19:40.956Z{"msg":"Crucible e23c53ab-882a-4e93-a55c-709811783430 has session id: 1e8c4398-97b1-4095-987e-86fdd96116c6","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.064010418Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2462025-03-17T22:19:40.956Z{"msg":"Upstairs opts: Upstairs UUID: e23c53ab-882a-4e93-a55c-709811783430, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: true, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.064046641Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2472025-03-17T22:19:40.956Z{"msg":"Crucible stats registered with UUID: e23c53ab-882a-4e93-a55c-709811783430","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.064062008Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2482025-03-17T22:19:40.956Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-03-17T22:19:40.064084374Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2492025-03-17T22:19:40.960Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.064917851Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"task":"crutest"}
2502025-03-17T22:19:40.960Z{"msg":"The guest has requested activation with gen:32","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.064943546Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236}
2512025-03-17T22:19:40.960Z{"msg":"e23c53ab-882a-4e93-a55c-709811783430 active request set","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.06502405Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2522025-03-17T22:19:40.960Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065067191Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"0","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2532025-03-17T22:19:40.960Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065108513Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"0","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2542025-03-17T22:19:40.960Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.06512513Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"1","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2552025-03-17T22:19:40.960Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065162213Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"1","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2562025-03-17T22:19:40.960Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065181379Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"2","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2572025-03-17T22:19:40.960Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065195786Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"2","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2582025-03-17T22:19:40.960Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065217942Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"io task","client":"2","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2592025-03-17T22:19:40.960Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065232339Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"io task","client":"0","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2602025-03-17T22:19:40.960Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065255945Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"io task","client":"1","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2612025-03-17T22:19:40.960Z{"msg":"ds_connection connected from Ok(127.0.0.1:51860)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065288508Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"io task","client":"2","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2622025-03-17T22:19:40.961Z{"msg":"ds_connection connected from Ok(127.0.0.1:48055)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065555816Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"io task","client":"1","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2632025-03-17T22:19:40.961Z{"msg":"ds_connection connected from Ok(127.0.0.1:56396)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.065597058Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"io task","client":"0","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2642025-03-17T22:19:40.961Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.066059707Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"1","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2652025-03-17T22:19:40.961Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.066108218Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"2","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2662025-03-17T22:19:40.961Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.066141392Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"0","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2672025-03-17T22:19:40.961Z{"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-03-17T22:19:40.066750952Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"0","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2682025-03-17T22:19:40.961Z{"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-03-17T22:19:40.066793734Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"1","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2692025-03-17T22:19:40.961Z{"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-03-17T22:19:40.066857481Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"2","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2702025-03-17T22:19:40.961Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067253564Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2712025-03-17T22:19:40.961Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067288757Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2722025-03-17T22:19:40.961Z{"msg":"[0]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067307743Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2732025-03-17T22:19:40.961Z{"msg":"[0]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.06732407Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2742025-03-17T22:19:40.961Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067337887Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2752025-03-17T22:19:40.961Z{"msg":"[1]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067359703Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2762025-03-17T22:19:40.961Z{"msg":"[1]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067373491Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2772025-03-17T22:19:40.961Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067399395Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2782025-03-17T22:19:40.961Z{"msg":"[2]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067412973Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2792025-03-17T22:19:40.961Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.06742787Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2802025-03-17T22:19:40.961Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067448676Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2812025-03-17T22:19:40.961Z{"msg":"Max found gen is 32","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067462333Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2822025-03-17T22:19:40.961Z{"msg":"Generation requested: 32 >= found:32","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067487978Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2832025-03-17T22:19:40.961Z{"msg":"Next flush: 1503","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067510514Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2842025-03-17T22:19:40.961Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067541498Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"":"downstairs","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2852025-03-17T22:19:40.961Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067566653Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2862025-03-17T22:19:40.961ZWait for a query_work_queue command to finish before sending IO
2872025-03-17T22:19:40.961Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067597657Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"0","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2882025-03-17T22:19:40.961Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067619782Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"1","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2892025-03-17T22:19:40.961Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067634029Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"client":"2","":"downstairs","session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2902025-03-17T22:19:40.961Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067663074Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2912025-03-17T22:19:40.961Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067701376Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2922025-03-17T22:19:40.961Z{"msg":"e23c53ab-882a-4e93-a55c-709811783430 is now active with session: 1e8c4398-97b1-4095-987e-86fdd96116c6","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067716564Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2932025-03-17T22:19:40.961Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067743768Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236,"session_id":"1e8c4398-97b1-4095-987e-86fdd96116c6"}
2942025-03-17T22:19:40.961Z{"msg":"The guest has finished waiting for activation with:32","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.067772273Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236}
2952025-03-17T22:19:40.961Z{"msg":"Activated sub_volume e23c53ab-882a-4e93-a55c-709811783430","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:40.06778599Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236}
2962025-03-17T22:19:40.961ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2972025-03-17T22:19:40.961ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
2982025-03-17T22:19:40.965ZFill test
2992025-03-17T22:19:40.998ZRead and Verify all blocks (0..50 range:false)
3002025-03-17T22:19:41.038ZWrote out file "/var/tmp/test_up-build/verify_file"
3012025-03-17T22:19:41.038ZCLIENT: Tests done. All submitted work has been ACK'd
3022025-03-17T22:19:41.041Z----------------------------------------------------------------
3032025-03-17T22:19:41.041Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:1
3042025-03-17T22:19:41.041ZStates: Active Active Active
3052025-03-17T22:19:41.041ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
3062025-03-17T22:19:41.041Z 1002 Acked Read 50 Done Done Done false
3072025-03-17T22:19:41.041Z STATES DS:0 DS:1 DS:2 TOTAL
3082025-03-17T22:19:41.041Z Sent 0 0 0 0
3092025-03-17T22:19:41.041Z Done 1 1 1 3
3102025-03-17T22:19:41.041Z Skipped 0 0 0 0
3112025-03-17T22:19:41.042Z Error 0 0 0 0
3122025-03-17T22:19:41.042ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
3132025-03-17T22:19:41.042ZDownstairs last five completed: 1001 1000
3142025-03-17T22:19:41.042ZUpstairs last five completed: 1002 1001 1000
3152025-03-17T22:19:41.042ZCLIENT: Up:0 ds:1 act:3
3162025-03-17T22:19:45.040Z----------------------------------------------------------------
3172025-03-17T22:19:45.040Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:0
3182025-03-17T22:19:45.040ZDownstairs last five completed: 1003 1002 1001 1000
3192025-03-17T22:19:45.040ZUpstairs last five completed: 1003 1002 1001 1000
3202025-03-17T22:19:45.040ZCLIENT: Up:0 ds:0 act:3
3212025-03-17T22:19:45.040ZCLIENT: All crucible jobs finished, exiting program
3222025-03-17T22:19:45.044Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-03-17T22:19:44.147419902Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1236}
3232025-03-17T22:19:45.047ZRepair part 1 passed
3242025-03-17T22:19:45.047Z
3252025-03-17T22:19:45.047ZKill the current downstairs
3262025-03-17T22:19:45.213ZDownstairs 2 stopped
3272025-03-17T22:19:45.213Zmv /var/tmp/test_up-build/8830 /var/tmp/test_up-build/new
3282025-03-17T22:19:45.216ZNow put back the original so we have a mismatch
3292025-03-17T22:19:45.216Zmv /var/tmp/test_up-build/previous /var/tmp/test_up-build/8830
3302025-03-17T22:19:45.220ZRestart downstairs with old directory
3312025-03-17T22:19:45.270Z/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
3322025-03-17T22:19:45.287ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
3332025-03-17T22:19:45.290Z 0 000-009 32 32 31 1503 1503 1502 F F F <---
3342025-03-17T22:19:45.291Z 1 010-019 32 32 31 1503 1503 1502 F F F <---
3352025-03-17T22:19:45.291Z 2 020-029 32 32 31 1503 1503 1502 F F F <---
3362025-03-17T22:19:45.291Z 3 030-039 32 32 31 1503 1503 1502 F F F <---
3372025-03-17T22:19:45.291Z 4 040-049 32 32 31 1503 1503 1502 F F F <---
3382025-03-17T22:19:45.291ZMax gen: 32, Max flush: 1503
3392025-03-17T22:19:45.510ZError: Difference in extent metadata found!
3402025-03-17T22:19:45.510Z
3412025-03-17T22:19:45.511ZStack backtrace:
3422025-03-17T22:19:45.511Z 0: anyhow::error::<impl anyhow::Error>::msg
3432025-03-17T22:19:45.511Z at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.96/src/backtrace.rs:27:14
3442025-03-17T22:19:45.511Z 1: anyhow::__private::format_err
3452025-03-17T22:19:45.511Z at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.96/src/lib.rs:691:13
3462025-03-17T22:19:45.530Zdump test found error as expected
3472025-03-17T22:19:45.533Z
3482025-03-17T22:19:45.533Z
3492025-03-17T22:19:45.533Z/var/tmp/bins/crutest verify --range -g 33 -q --key FgdTkwR/arb2Vtm7ywkckbWUQ3+Pwe0qko6mFjLUpg4= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
3502025-03-17T22:19:45.587Z{"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-03-17T22:19:44.693662236Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"task":"crutest"}
3512025-03-17T22:19:45.590Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.694236243Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"task":"crutest"}
3522025-03-17T22:19:45.590Z{"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-03-17T22:19:44.695969994Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"task":"crutest"}
3532025-03-17T22:19:45.590Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.696159197Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244}
3542025-03-17T22:19:45.590Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"f72bfdb36aa576722b377a737f26a9b5ef54faf2\",\n git_commit_timestamp: \"2025-03-17T21:58:36.000000000Z\",\n git_branch: \"renovate/tempfile-3.x-lockfile\",\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-03-17T22:19:44.696212487Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244}
3552025-03-17T22:19:45.590Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.696269326Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244}
3562025-03-17T22:19:45.590Z{"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 10, shift: 12 }, extent_count: 5, uuid: 00000000-0000-0000-0000-000000000000, encrypted: true, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.696289062Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244}
3572025-03-17T22:19:45.590Z{"msg":"Crucible 8f76e261-024b-4593-afdd-4560b3a76b09 has session id: 9fbc9331-9508-4faa-955d-42e2338315a8","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.696829426Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3582025-03-17T22:19:45.590Z{"msg":"Upstairs opts: Upstairs UUID: 8f76e261-024b-4593-afdd-4560b3a76b09, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: true, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.696879327Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3592025-03-17T22:19:45.590Z{"msg":"Crucible stats registered with UUID: 8f76e261-024b-4593-afdd-4560b3a76b09","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.696904831Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3602025-03-17T22:19:45.590Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-03-17T22:19:44.696934216Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3612025-03-17T22:19:45.594Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.697703965Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"task":"crutest"}
3622025-03-17T22:19:45.594Z{"msg":"The guest has requested activation with gen:33","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.697748397Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244}
3632025-03-17T22:19:45.594Z{"msg":"8f76e261-024b-4593-afdd-4560b3a76b09 active request set","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.697854906Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3642025-03-17T22:19:45.594Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.697896397Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"0","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3652025-03-17T22:19:45.594Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.69793578Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"0","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3662025-03-17T22:19:45.594Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.697953836Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"1","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3672025-03-17T22:19:45.594Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.69798596Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"1","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3682025-03-17T22:19:45.594Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.698011345Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3692025-03-17T22:19:45.594Z{"msg":"client set_active_request while in Connecting { state: Start { auto_promote: true }, mode: New }; waiting...","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.698044169Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3702025-03-17T22:19:45.594Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.698060265Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3712025-03-17T22:19:45.594Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.6980891Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"0","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3722025-03-17T22:19:45.594Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.698111355Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"1","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3732025-03-17T22:19:45.594Z{"msg":"ds_connection connected from Ok(127.0.0.1:46332)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.698144049Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"0","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3742025-03-17T22:19:45.594Z{"msg":"ds_connection connected from Ok(127.0.0.1:63032)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.698166695Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"1","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3752025-03-17T22:19:45.594Z{"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-03-17T22:19:44.698200018Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3762025-03-17T22:19:45.595Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2025-03-17T22:19:44.698226703Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3772025-03-17T22:19:45.595Z{"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-03-17T22:19:44.698405198Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3782025-03-17T22:19:45.595Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.698557888Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3792025-03-17T22:19:45.595Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.699043193Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"0","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3802025-03-17T22:19:45.595Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.699100972Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"1","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3812025-03-17T22:19:45.595Z{"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-03-17T22:19:44.699655964Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"1","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3822025-03-17T22:19:45.595Z{"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-03-17T22:19:44.699697665Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"0","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3832025-03-17T22:19:45.595Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.700103156Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3842025-03-17T22:19:45.595Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:44.700149757Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3852025-03-17T22:19:55.595Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.699754221Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3862025-03-17T22:19:55.600Z{"msg":"ds_connection connected from Ok(127.0.0.1:34833)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.700083777Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3872025-03-17T22:19:55.600Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.700983871Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3882025-03-17T22:19:55.600Z{"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-03-17T22:19:54.701563778Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3892025-03-17T22:19:55.600Z{"msg":"[0]R flush_numbers: [1503, 1503, 1503, 1503, 1503]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.701999092Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3902025-03-17T22:19:55.600Z{"msg":"[0]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702036965Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3912025-03-17T22:19:55.600Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702054322Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3922025-03-17T22:19:55.600Z{"msg":"[1]R flush_numbers: [1503, 1503, 1503, 1503, 1503]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702076117Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3932025-03-17T22:19:55.600Z{"msg":"[1]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702090455Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3942025-03-17T22:19:55.600Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.7021126Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3952025-03-17T22:19:55.600Z{"msg":"[2]R flush_numbers: [1502, 1502, 1502, 1502, 1502]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702127107Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3962025-03-17T22:19:55.600Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702147923Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3972025-03-17T22:19:55.600Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.70216252Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3982025-03-17T22:19:55.600Z{"msg":"Max found gen is 33","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702182357Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
3992025-03-17T22:19:55.600Z{"msg":"Generation requested: 33 >= found:33","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702195864Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4002025-03-17T22:19:55.600Z{"msg":"Next flush: 1504","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.70221537Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4012025-03-17T22:19:55.600Z{"msg":"extent 0 needs reconciliation: ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 31, flush: 1502, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702230907Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4022025-03-17T22:19:55.600Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 31, flush: 1502, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702253393Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4032025-03-17T22:19:55.600Z{"msg":"found dest for source 0 for extent at index 0 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.70226821Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4042025-03-17T22:19:55.600Z{"msg":"extent 1 needs reconciliation: ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 31, flush: 1502, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702290185Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4052025-03-17T22:19:55.600Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 31, flush: 1502, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702306112Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4062025-03-17T22:19:55.600Z{"msg":"found dest for source 0 for extent at index 1 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702319979Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4072025-03-17T22:19:55.600Z{"msg":"extent 2 needs reconciliation: ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 31, flush: 1502, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702341835Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4082025-03-17T22:19:55.600Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 31, flush: 1502, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702357342Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4092025-03-17T22:19:55.600Z{"msg":"found dest for source 0 for extent at index 2 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.70237198Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4102025-03-17T22:19:55.600Z{"msg":"extent 3 needs reconciliation: ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 31, flush: 1502, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702387486Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4112025-03-17T22:19:55.601Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 31, flush: 1502, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702411732Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4122025-03-17T22:19:55.601Z{"msg":"found dest for source 0 for extent at index 3 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702435137Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4132025-03-17T22:19:55.601Z{"msg":"extent 4 needs reconciliation: ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 32, flush: 1503, dirty: false } ExtentMetadata { gen: 31, flush: 1502, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702451424Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4142025-03-17T22:19:55.601Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 32, flush: 1503, dirty: false }, ExtentMetadata { gen: 31, flush: 1502, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702467671Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4152025-03-17T22:19:55.601Z{"msg":"found dest for source 0 for extent at index 4 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702488287Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4162025-03-17T22:19:55.601Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702513142Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"0","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4172025-03-17T22:19:55.601Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702536227Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"1","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4182025-03-17T22:19:55.601Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702550305Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4192025-03-17T22:19:55.601Z{"msg":"Full repair list: {ExtentId(4): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(3): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(0): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(2): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(1): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }}","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702575Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4202025-03-17T22:19:55.601Z{"msg":"Task list: [ReconcileIO { id: ReconciliationId(0), op: ExtentFlush { repair_id: ReconciliationId(0), extent_id: ExtentId(4), client_id: ClientId(0), flush_number: 1504, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(1), op: ExtentClose { repair_id: ReconciliationId(1), extent_id: ExtentId(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(3), client_id: ClientId(0), flush_number: 1504, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(5), op: ExtentClose { repair_id: ReconciliationId(5), extent_id: ExtentId(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(0), client_id: ClientId(0), flush_number: 1504, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(9), op: ExtentClose { repair_id: ReconciliationId(9), extent_id: ExtentId(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: 1504, 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(1), client_id: ClientId(0), flush_number: 1504, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(17), op: ExtentClose { repair_id: ReconciliationId(17), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(18), op: ExtentRepair { repair_id: ReconciliationId(18), 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(19), op: ExtentReopen { repair_id: ReconciliationId(19), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }]","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702668851Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4212025-03-17T22:19:55.601Z{"msg":"starting reconciliation 7c69aa77-01df-42d6-a6d9-d58373bb1973: found 20 extents that need repair","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.702697436Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4222025-03-17T22:19:55.601Z{"msg":"sending reconcile request ReconciliationId(2)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.703021642Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4232025-03-17T22:19:55.610Z{"msg":"sending reconcile request ReconciliationId(6)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.714935563Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4242025-03-17T22:19:55.613Z{"msg":"sending reconcile request ReconciliationId(10)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.718535569Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4252025-03-17T22:19:55.622Z{"msg":"sending reconcile request ReconciliationId(14)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.722232766Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4262025-03-17T22:19:55.625Z{"msg":"sending reconcile request ReconciliationId(18)","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.725778523Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4272025-03-17T22:19:55.625Z{"msg":"done with reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.728930416Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"":"downstairs","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4282025-03-17T22:19:55.625Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.728969039Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"0","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4292025-03-17T22:19:55.625Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.728986096Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"1","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4302025-03-17T22:19:55.625Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.729000483Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"client":"2","":"downstairs","session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4312025-03-17T22:19:55.625Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.72901423Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4322025-03-17T22:19:55.625Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.729028097Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4332025-03-17T22:19:55.625Z{"msg":"8f76e261-024b-4593-afdd-4560b3a76b09 is now active with session: 9fbc9331-9508-4faa-955d-42e2338315a8","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.729041825Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244,"session_id":"9fbc9331-9508-4faa-955d-42e2338315a8"}
4342025-03-17T22:19:55.625Z{"msg":"The guest has finished waiting for activation with:33","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.729054852Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244}
4352025-03-17T22:19:55.625Z{"msg":"Activated sub_volume 8f76e261-024b-4593-afdd-4560b3a76b09","v":0,"name":"crucible","level":30,"time":"2025-03-17T22:19:54.729068569Z","hostname":"w-01JPK2S2SFWTFT81E1XH9PKWDH","pid":1244}
4362025-03-17T22:19:55.625ZWait for a query_work_queue command to finish before sending IO
4372025-03-17T22:19:55.625ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
4382025-03-17T22:19:55.625ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
4392025-03-17T22:19:55.625ZRead and Verify all blocks (0..50 range:true)
4402025-03-17T22:19:55.664ZWrote out file "/var/tmp/test_up-build/verify_file"
4412025-03-17T22:19:55.664ZVerify test completed
4422025-03-17T22:19:55.668ZWrote out file "/var/tmp/test_up-build/verify_file"
4432025-03-17T22:19:55.668ZCLIENT: Tests done. All submitted work has been ACK'd
4442025-03-17T22:19:55.668Z----------------------------------------------------------------
4452025-03-17T22:19:55.668Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:1
4462025-03-17T22:19:55.668ZStates: Active Active Active
4472025-03-17T22:19:55.668ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
4482025-03-17T22:19:55.668Z 1000 Acked Read 50 Done Done Done false
4492025-03-17T22:19:55.668Z STATES DS:0 DS:1 DS:2 TOTAL
4502025-03-17T22:19:55.668Z Sent 0 0 0 0
4512025-03-17T22:19:55.668Z Done 1 1 1 3
4522025-03-17T22:19:55.668Z Skipped 0 0 0 0
4532025-03-17T22:19:55.668Z Error 0 0 0 0
4542025-03-17T22:19:55.668ZLast Flush: None None None
4552025-03-17T22:19:55.668ZDownstairs last five completed:
4562025-03-17T22:19:55.668ZUpstairs last five completed: 1000
4572025-03-17T22:19:55.668ZCLIENT: Up:0 ds:1 act:3
4582025-03-17T22:19:59.668Z----------------------------------------------------------------
4592025-03-17T22:19:59.668Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:0
4602025-03-17T22:19:59.668ZDownstairs last five completed: 1001 1000
4612025-03-17T22:19:59.668ZUpstairs last five completed: 1001 1000
4622025-03-17T22:19:59.668ZCLIENT: Up:0 ds:0 act:3
4632025-03-17T22:19:59.668ZCLIENT: All crucible jobs finished, exiting program
4642025-03-17T22:19:59.674ZRepair part 2 passed
4652025-03-17T22:19:59.677Z/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
4662025-03-17T22:19:59.692ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
4672025-03-17T22:19:59.692Z 0 000-009 32 32 32 1503 1503 1503 F F F
4682025-03-17T22:19:59.695Z 1 010-019 32 32 32 1503 1503 1503 F F F
4692025-03-17T22:19:59.695Z 2 020-029 32 32 32 1503 1503 1503 F F F
4702025-03-17T22:19:59.695Z 3 030-039 32 32 32 1503 1503 1503 F F F
4712025-03-17T22:19:59.695Z 4 040-049 32 32 32 1503 1503 1503 F F F
4722025-03-17T22:19:59.695ZMax gen: 32, Max flush: 1503
4732025-03-17T22:19:59.699Zdump test passed
4742025-03-17T22:19:59.699Z/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
4752025-03-17T22:19:59.714Z Extent 1
4762025-03-17T22:19:59.717ZGEN 32 32 32
4772025-03-17T22:19:59.717ZFLUSH_ID 1503 1503 1503
4782025-03-17T22:19:59.717ZDIRTY
4792025-03-17T22:19:59.717Z
4802025-03-17T22:19:59.717ZBLOCK D0 D1 D2 C0 C1 C2 DIFF
4812025-03-17T22:19:59.717Z010 A A A A A A
4822025-03-17T22:19:59.720Z011 A A A A A A
4832025-03-17T22:19:59.720Z012 A A A A A A
4842025-03-17T22:19:59.720Z013 A A A A A A
4852025-03-17T22:19:59.723Z014 A A A A A A
4862025-03-17T22:19:59.723Z015 A A A A A A
4872025-03-17T22:19:59.726Z016 A A A A A A
4882025-03-17T22:19:59.726Z017 A A A A A A
4892025-03-17T22:19:59.729Z018 A A A A A A
4902025-03-17T22:19:59.729Z019 A A A A A A
4912025-03-17T22:19:59.733Zdump extent test passed
4922025-03-17T22:19:59.733Z/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
4932025-03-17T22:19:59.747ZExtent 2 Block in extent 0 Actual block 20
4942025-03-17T22:19:59.747Z
4952025-03-17T22:19:59.750Z DATA SHA256 VER
4962025-03-17T22:19:59.750Z------ ---------------------------------------------------------------- ---
4972025-03-17T22:19:59.750Z 0 cc72dd56815333570f8c391ac4be1289a68169180222b7a52e7179592f08d096 A
4982025-03-17T22:19:59.750Z 1 cc72dd56815333570f8c391ac4be1289a68169180222b7a52e7179592f08d096 A
4992025-03-17T22:19:59.750Z 2 cc72dd56815333570f8c391ac4be1289a68169180222b7a52e7179592f08d096 A
5002025-03-17T22:19:59.750Z
5012025-03-17T22:19:59.750ZNONCES 0 1 2 DIFF
5022025-03-17T22:19:59.750Z------ ------------------------ ------------------------ ------------------------ -----
5032025-03-17T22:19:59.750Z 0 27e784aec57916ca3af99e27 27e784aec57916ca3af99e27 27e784aec57916ca3af99e27
5042025-03-17T22:19:59.750Z
5052025-03-17T22:19:59.750Z TAGS 0 1 2 DIFF
5062025-03-17T22:19:59.750Z------ -------------------------------- -------------------------------- -------------------------------- -----
5072025-03-17T22:19:59.750Z 0 696f73e65e3d56794012f7d276025b3d 696f73e65e3d56794012f7d276025b3d 696f73e65e3d56794012f7d276025b3d
5082025-03-17T22:19:59.751Z
5092025-03-17T22:19:59.754ZHASHES 0 1 2 DIFF
5102025-03-17T22:19:59.754Z------ ---------------- ---------------- ---------------- -----
5112025-03-17T22:19:59.754Z
5122025-03-17T22:19:59.754Zdump block test passed
5132025-03-17T22:19:59.754ZInitial upstairs tests have completed, stopping all downstairs
5142025-03-17T22:20:04.818ZCreating 4 larger downstairs regions
5152025-03-17T22:20:04.932ZStarting 4 downstairs
5162025-03-17T22:20:09.940Zdsc restarted at PID: 1257
5172025-03-17T22:20:10.158ZNow do the replace-reconcile test
5182025-03-17T22:20:10.212ZUsing 8840 for the replacement port
5192025-03-17T22:22:45.013ZCompleted test: replace-reconcile
5202025-03-17T22:22:45.017ZNow do the replace-before-active test
5212025-03-17T22:25:51.819ZCompleted test: replace-before-active
5222025-03-17T22:25:51.827ZAll tests have completed, stopping all downstairs
5232025-03-17T22:25:51.871Z
5242025-03-17T22:25:51.871ZAll Tests have passed
5252025-03-17T22:25:51.875Z9:40 Test duration
5262025-03-17T22:25:51.875Z
5272025-03-17T22:25:51.875Zreal 9:40.465771025
5282025-03-17T22:25:51.875Zuser 6:25.201171165
5292025-03-17T22:25:51.875Zsys 11.920574022
5302025-03-17T22:25:51.875Ztrap 0.186561965
5312025-03-17T22:25:51.875Ztflt 0.025690285
5322025-03-17T22:25:51.875Zdflt 0.019419670
5332025-03-17T22:25:51.875Zkflt 0.001331591
5342025-03-17T22:25:51.875Zlock 8:36:18.823291531
5352025-03-17T22:25:51.875Zslp 33:49.814070958
5362025-03-17T22:25:51.875Zlat 23.550831154
5372025-03-17T22:25:51.875Zstop 0.126908022
5382025-03-17T22:25:51.876Z+ echo 'test-up-encrypted ends'
5392025-03-17T22:25:51.876Ztest-up-encrypted ends
5402025-03-17T22:25:56.878Zprocess exited: duration 588914 ms, exit code 0
5412025-03-17T22:25:56.878Zexec warning: : stdio descriptors remain open after task exit; waiting 60 seconds for them to close
5422025-03-17T22:26:56.936Zexec warning: : stdout descriptor may be held open by a background process; giving up!
5432025-03-17T22:26:56.936Zexec warning: : stderr descriptor may be held open by a background process; giving up!
 
5442025-03-17T22:26:56.948Zfound 14 output files
5452025-03-17T22:26:56.948Zuploading: /tmp/test_up-build/dsc-out.txt (37782 bytes)
5462025-03-17T22:26:57.962Zuploaded: /tmp/test_up-build/dsc-out.txt
5472025-03-17T22:26:57.972Zuploading: /tmp/test_up-build/test_up_out.txt (7490486 bytes)
5482025-03-17T22:26:59.155Zuploaded: /tmp/test_up-build/test_up_out.txt
5492025-03-17T22:26:59.159Zuploading: /tmp/test_up-build/dsc/downstairs-8810.txt (2507 bytes)
5502025-03-17T22:27:00.169Zuploaded: /tmp/test_up-build/dsc/downstairs-8810.txt
5512025-03-17T22:27:00.172Zuploading: /tmp/test_up-build/dsc/downstairs-8820.txt (144636 bytes)
5522025-03-17T22:27:01.196Zuploaded: /tmp/test_up-build/dsc/downstairs-8820.txt
5532025-03-17T22:27:01.196Zuploading: /tmp/test_up-build/dsc/downstairs-8830.txt (251002 bytes)
5542025-03-17T22:27:02.232Zuploaded: /tmp/test_up-build/dsc/downstairs-8830.txt
5552025-03-17T22:27:02.235Zuploading: /tmp/test_up-build/dsc/downstairs-8840.txt (139426 bytes)
5562025-03-17T22:27:03.259Zuploaded: /tmp/test_up-build/dsc/downstairs-8840.txt
5572025-03-17T22:27:03.266Zuploading: /tmp/debug/df.txt (1270 bytes)
5582025-03-17T22:27:04.279Zuploaded: /tmp/debug/df.txt
5592025-03-17T22:27:04.282Zuploading: /tmp/debug/dtrace.txt (447389 bytes)
5602025-03-17T22:27:05.323Zuploaded: /tmp/debug/dtrace.txt
5612025-03-17T22:27:05.326Zuploading: /tmp/debug/iostat.txt (192547 bytes)
5622025-03-17T22:27:05.349Zupload warning: file "/tmp/debug/iostat.txt" changed size mid upload: 192547 -> 194931
5632025-03-17T22:27:06.358Zuploaded: /tmp/debug/iostat.txt
5642025-03-17T22:27:06.358Zuploading: /tmp/debug/mpstat.txt (469649 bytes)
5652025-03-17T22:27:06.398Zupload warning: file "/tmp/debug/mpstat.txt" changed size mid upload: 469649 -> 476192
5662025-03-17T22:27:07.406Zuploaded: /tmp/debug/mpstat.txt
5672025-03-17T22:27:07.409Zuploading: /tmp/debug/paging.txt (83268 bytes)
5682025-03-17T22:27:07.424Zupload warning: file "/tmp/debug/paging.txt" changed size mid upload: 83268 -> 84669
5692025-03-17T22:27:08.431Zuploaded: /tmp/debug/paging.txt
5702025-03-17T22:27:08.432Zuploading: /tmp/debug/prstat.txt (899016 bytes)
5712025-03-17T22:27:08.486Zupload warning: file "/tmp/debug/prstat.txt" changed size mid upload: 899016 -> 913266
5722025-03-17T22:27:09.496Zuploaded: /tmp/debug/prstat.txt
5732025-03-17T22:27:09.499Zuploading: /tmp/debug/psrinfo.txt (1528 bytes)
5742025-03-17T22:27:10.506Zuploaded: /tmp/debug/psrinfo.txt
5752025-03-17T22:27:10.509Zuploading: /tmp/debug/upstairs-info.txt (69300 bytes)
5762025-03-17T22:27:11.527Zuploaded: /tmp/debug/upstairs-info.txt