01JPKRZEMTTKCNQXMZDRKP0XFM: 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: 01JPKS04N8E47T773H1MF1JKS3

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-03-18T04:57:16.793Zjob dependencies complete; ready to run (waiting for 14 m 4 s)
22025-03-18T04:58:13.368Zjob assigned to worker 01JPKST5XC2HZ2QYN8PJ049NF1 [factory aws, i-01df99e22bf4314b7] (queued for 56 s)
32025-03-18T04:58:22.185Zdownloading input: /input/build/work/bins/crucible-downstairs.gz
42025-03-18T04:58:24.069Zdownloaded input: /input/build/work/bins/crucible-downstairs.gz
52025-03-18T04:58:24.069Zdownloading input: /input/build/work/bins/crucible-hammer.gz
62025-03-18T04:58:25.833Zdownloaded input: /input/build/work/bins/crucible-hammer.gz
72025-03-18T04:58:25.833Zdownloading input: /input/build/work/bins/crutest.gz
82025-03-18T04:58:28.253Zdownloaded input: /input/build/work/bins/crutest.gz
92025-03-18T04:58:28.253Zdownloading input: /input/build/work/bins/dsc.gz
102025-03-18T04:58:29.456Zdownloaded input: /input/build/work/bins/dsc.gz
112025-03-18T04:58:29.460Zdownloading input: /input/build/work/scripts/perf-downstairs-tick.d
122025-03-18T04:58:29.476Zdownloaded input: /input/build/work/scripts/perf-downstairs-tick.d
132025-03-18T04:58:29.476Zdownloading input: /input/build/work/scripts/test_ds.sh
142025-03-18T04:58:29.494Zdownloaded input: /input/build/work/scripts/test_ds.sh
152025-03-18T04:58:29.494Zdownloading input: /input/build/work/scripts/test_live_repair.sh
162025-03-18T04:58:29.512Zdownloaded input: /input/build/work/scripts/test_live_repair.sh
172025-03-18T04:58:29.512Zdownloading input: /input/build/work/scripts/test_repair.sh
182025-03-18T04:58:29.532Zdownloaded input: /input/build/work/scripts/test_repair.sh
192025-03-18T04:58:29.532Zdownloading input: /input/build/work/scripts/test_replay.sh
202025-03-18T04:58:29.557Zdownloaded input: /input/build/work/scripts/test_replay.sh
212025-03-18T04:58:29.557Zdownloading input: /input/build/work/scripts/test_up.sh
222025-03-18T04:58:29.579Zdownloaded input: /input/build/work/scripts/test_up.sh
232025-03-18T04:58:29.579Zdownloading input: /input/build/work/scripts/upstairs_info.d
242025-03-18T04:58:29.595Zdownloaded input: /input/build/work/scripts/upstairs_info.d
252025-03-18T04:58:29.599Zdownloading input: /input/build/tmp/cargo-test-out.log
262025-03-18T04:58:30.270Zdownloaded input: /input/build/tmp/cargo-test-out.log
 
272025-03-18T04:58:30.270Zstarting task 0: "setup"
282025-03-18T04:58:30.276Z++ uname -s
292025-03-18T04:58:30.276Z+ kern=SunOS
302025-03-18T04:58:30.276Z+ build_user=build
312025-03-18T04:58:30.276Z+ build_uid=12345
322025-03-18T04:58:30.276Z+ work_dir=/work
332025-03-18T04:58:30.276Z+ input_dir=/input
342025-03-18T04:58:30.276Z+ [[ 0 == 12345 ]]
352025-03-18T04:58:30.276Z+ case "$kern" in
362025-03-18T04:58:30.276Z+ groupadd -g 12345 build
372025-03-18T04:58:30.276Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
382025-03-18T04:58:32.283Z+ zfs create -o mountpoint=/work rpool/work
392025-03-18T04:58:32.509Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
402025-03-18T04:58:32.515Z+ home_fs=zfs
412025-03-18T04:58:32.515Z+ [[ zfs == autofs ]]
422025-03-18T04:58:32.515Z+ mkdir -p /home/build
432025-03-18T04:58:32.515Z+ chown build:build /home/build /work
442025-03-18T04:58:33.508Z+ chmod 0700 /home/build /work
452025-03-18T04:58:33.512Zprocess exited: duration 3249 ms, exit code 0
 
462025-03-18T04:58:33.520Zstarting task 1: "authentication"
472025-03-18T04:58:33.540Zprocess exited: duration 19 ms, exit code 0
 
482025-03-18T04:58:33.551Zstarting task 2: "build"
492025-03-18T04:58:33.576Z+ banner cores
502025-03-18T04:58:33.584Z
512025-03-18T04:58:33.584Z #### #### ##### ###### ####
522025-03-18T04:58:33.584Z # # # # # # # #
532025-03-18T04:58:33.584Z # # # # # ##### ####
542025-03-18T04:58:33.584Z # # # ##### # #
552025-03-18T04:58:33.584Z # # # # # # # # #
562025-03-18T04:58:33.584Z #### #### # # ###### ####
572025-03-18T04:58:33.584Z
582025-03-18T04:58:33.584Z+ pfexec coreadm -i /tmp/core.%f.%p -g /tmp/core.%f.%p -e global -e log -e proc-setid -e global-setid
592025-03-18T04:58:33.585Z+ echo 'input bins dir contains:'
602025-03-18T04:58:33.585Zinput bins dir contains:
612025-03-18T04:58:33.585Z+ ls -ltr /input/build/work/bins
622025-03-18T04:58:33.585Ztotal 793869
632025-03-18T04:58:33.585Z-rw-r--r-- 1 root root 118603803 Mar 18 04:58 crucible-downstairs.gz
642025-03-18T04:58:33.585Z-rw-r--r-- 1 root root 106091686 Mar 18 04:58 crucible-hammer.gz
652025-03-18T04:58:33.585Z-rw-r--r-- 1 root root 115348358 Mar 18 04:58 crutest.gz
662025-03-18T04:58:33.585Z-rw-r--r-- 1 root root 66141326 Mar 18 04:58 dsc.gz
672025-03-18T04:58:33.585Z+ banner unpack
682025-03-18T04:58:33.585Z
692025-03-18T04:58:33.585Z # # # # ##### ## #### # #
702025-03-18T04:58:33.585Z # # ## # # # # # # # # #
712025-03-18T04:58:33.585Z # # # # # # # # # # ####
722025-03-18T04:58:33.585Z # # # # # ##### ###### # # #
732025-03-18T04:58:33.585Z # # # ## # # # # # # #
742025-03-18T04:58:33.585Z #### # # # # # #### # #
752025-03-18T04:58:33.585Z
762025-03-18T04:58:33.585Z+ mkdir -p /var/tmp/bins
772025-03-18T04:58:33.585Z+ for t in "$input/bins/"*.gz
782025-03-18T04:58:33.585Z++ basename /input/build/work/bins/crucible-downstairs.gz
792025-03-18T04:58:33.586Z+ b=crucible-downstairs.gz
802025-03-18T04:58:33.586Z+ b=crucible-downstairs
812025-03-18T04:58:33.586Z+ gunzip
822025-03-18T04:58:36.013Z+ chmod +x /var/tmp/bins/crucible-downstairs
832025-03-18T04:58:36.018Z+ for t in "$input/bins/"*.gz
842025-03-18T04:58:36.019Z++ basename /input/build/work/bins/crucible-hammer.gz
852025-03-18T04:58:36.019Z+ b=crucible-hammer.gz
862025-03-18T04:58:36.019Z+ b=crucible-hammer
872025-03-18T04:58:36.019Z+ gunzip
882025-03-18T04:58:38.281Z+ chmod +x /var/tmp/bins/crucible-hammer
892025-03-18T04:58:38.301Z+ for t in "$input/bins/"*.gz
902025-03-18T04:58:38.301Z++ basename /input/build/work/bins/crutest.gz
912025-03-18T04:58:38.301Z+ b=crutest.gz
922025-03-18T04:58:38.301Z+ b=crutest
932025-03-18T04:58:38.301Z+ gunzip
942025-03-18T04:58:40.618Z+ chmod +x /var/tmp/bins/crutest
952025-03-18T04:58:40.628Z+ for t in "$input/bins/"*.gz
962025-03-18T04:58:40.628Z++ basename /input/build/work/bins/dsc.gz
972025-03-18T04:58:40.628Z+ b=dsc.gz
982025-03-18T04:58:40.628Z+ b=dsc
992025-03-18T04:58:40.628Z+ gunzip
1002025-03-18T04:58:42.021Z+ chmod +x /var/tmp/bins/dsc
1012025-03-18T04:58:42.054Z+ export BINDIR=/var/tmp/bins
1022025-03-18T04:58:42.054Z+ BINDIR=/var/tmp/bins
1032025-03-18T04:58:42.054Z+ export RUST_BACKTRACE=1
1042025-03-18T04:58:42.054Z+ RUST_BACKTRACE=1
1052025-03-18T04:58:42.054Z+ jobpid=1147
1062025-03-18T04:58:42.054Z+ echo 'Setup debug logging'
1072025-03-18T04:58:42.055ZSetup debug logging
1082025-03-18T04:58:42.055Z+ mkdir /tmp/debug
1092025-03-18T04:58:42.055Z+ sleep 3600
1102025-03-18T04:58:42.055Z+ psrinfo -v
1112025-03-18T04:58:42.055Z+ df -h
1122025-03-18T04:58:42.055Z+ prstat -d d -mLc 1
1132025-03-18T04:58:42.055Z+ iostat -T d -xn 1
1142025-03-18T04:58:42.055Z+ mpstat -T d 1
1152025-03-18T04:58:42.055Z+ vmstat -T d -p 1
1162025-03-18T04:58:42.055Z+ pfexec dtrace -Z -s /input/build/work/scripts/perf-downstairs-tick.d
1172025-03-18T04:58:42.056Z+ banner test_up_encrypted
1182025-03-18T04:58:42.056Z+ pfexec dtrace -Z -s /input/build/work/scripts/upstairs_info.d
1192025-03-18T04:58:42.056Z
1202025-03-18T04:58:42.056Z ##### ###### #### ##### # # ##### ###### # #
1212025-03-18T04:58:42.056Z # # # # # # # # # ## #
1222025-03-18T04:58:42.056Z # ##### #### # # # # # ##### # # #
1232025-03-18T04:58:42.056Z # # # # # # ##### # # # #
1242025-03-18T04:58:42.056Z # # # # # # # # # # ##
1252025-03-18T04:58:42.056Z # ###### #### # ####### #### # ####### ###### # #
1262025-03-18T04:58:42.056Z
1272025-03-18T04:58:42.056Z+ ptime -m bash /input/build/work/scripts/test_up.sh -N encrypted
1282025-03-18T04:58:42.056Z/input/build/work
1292025-03-18T04:58:42.093ZTurn off color for downstairs dump
1302025-03-18T04:58:42.093ZUpstairs using key: QUdMCMAgZhw5pa+L+eeMc37iRhk+etMJJKLhh5Gxz+8=
1312025-03-18T04:58:42.093Zdsc output goes to /tmp/test_up-build/dsc-out.txt
1322025-03-18T04:58:42.093ZCreating 3 downstairs regions
1332025-03-18T04:58:42.383ZStarting 3 downstairs
1342025-03-18T04:58:42.406Zdsc started at PID: 1193
1352025-03-18T04:58:47.570ZDisable automatic restart on all downstairs
1362025-03-18T04:58:47.618Z
1372025-03-18T04:58:47.619ZBegin tests, output goes to /tmp/test_up-build/test_up_out.txt
1382025-03-18T04:58:47.634ZRunning test: span
1392025-03-18T04:58:51.751ZCompleted test: span
1402025-03-18T04:58:56.766ZRunning test: big
1412025-03-18T04:59:01.056ZCompleted test: big
1422025-03-18T04:59:06.074ZRunning test: dep
1432025-03-18T04:59:57.943ZCompleted test: dep
1442025-03-18T05:00:02.951ZRunning test: balloon
1452025-03-18T05:00:43.284ZCompleted test: balloon
1462025-03-18T05:00:48.294ZRunning test: deactivate
1472025-03-18T05:01:42.929ZCompleted test: deactivate
1482025-03-18T05:01:47.936ZRunning hammer
1492025-03-18T05:02:00.979ZRun repair tests
1502025-03-18T05:02:00.983Z/var/tmp/bins/crutest fill -g 31 -q --key QUdMCMAgZhw5pa+L+eeMc37iRhk+etMJJKLhh5Gxz+8= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file
1512025-03-18T05:02:01.041Z{"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-18T05:01:59.680540014Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"task":"crutest"}
1522025-03-18T05:02:01.044Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.681135638Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"task":"crutest"}
1532025-03-18T05:02:01.045Z{"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-18T05:01:59.682803189Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"task":"crutest"}
1542025-03-18T05:02:01.045Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.683015143Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230}
1552025-03-18T05:02:01.045Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"15e44c06f41a7116c9cfd33f9c32fc1c3d097c63\",\n git_commit_timestamp: \"2025-03-18T04:42:20.000000000Z\",\n git_branch: \"renovate/anyhow-1.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-18T05:01:59.683068249Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230}
1562025-03-18T05:02:01.045Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.683093087Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230}
1572025-03-18T05:02:01.045Z{"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-18T05:01:59.683108575Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230}
1582025-03-18T05:02:01.045Z{"msg":"Crucible 6a7e5255-ddd7-4b5a-8644-6c72d5ae7b2e has session id: 8ef8cb99-0818-4464-9b91-c30d4dc6a26c","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.683744656Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1592025-03-18T05:02:01.045Z{"msg":"Upstairs opts: Upstairs UUID: 6a7e5255-ddd7-4b5a-8644-6c72d5ae7b2e, 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-18T05:01:59.683802922Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1602025-03-18T05:02:01.045Z{"msg":"Crucible stats registered with UUID: 6a7e5255-ddd7-4b5a-8644-6c72d5ae7b2e","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.683838499Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1612025-03-18T05:02:01.045Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-03-18T05:01:59.683855898Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1622025-03-18T05:02:01.050Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.684872329Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"task":"crutest"}
1632025-03-18T05:02:01.051Z{"msg":"The guest has requested activation with gen:31","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.684925435Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230}
1642025-03-18T05:02:01.051Z{"msg":"6a7e5255-ddd7-4b5a-8644-6c72d5ae7b2e active request set","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.684952233Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1652025-03-18T05:02:01.051Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.6849858Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"0","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1662025-03-18T05:02:01.051Z{"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-18T05:01:59.685058675Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"0","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1672025-03-18T05:02:01.051Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.685081363Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"1","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1682025-03-18T05:02:01.051Z{"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-18T05:01:59.68511717Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"1","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1692025-03-18T05:02:01.051Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.685135389Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"2","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1702025-03-18T05:02:01.051Z{"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-18T05:01:59.685164247Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"2","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1712025-03-18T05:02:01.051Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.685195414Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"io task","client":"2","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1722025-03-18T05:02:01.051Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.685217372Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"io task","client":"0","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1732025-03-18T05:02:01.051Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.685240041Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"io task","client":"1","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1742025-03-18T05:02:01.051Z{"msg":"ds_connection connected from Ok(127.0.0.1:62585)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.685272958Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"io task","client":"2","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1752025-03-18T05:02:01.051Z{"msg":"ds_connection connected from Ok(127.0.0.1:52367)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.685336413Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"io task","client":"1","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1762025-03-18T05:02:01.051Z{"msg":"ds_connection connected from Ok(127.0.0.1:58287)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.68537016Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"io task","client":"0","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1772025-03-18T05:02:01.051Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.686196177Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"0","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1782025-03-18T05:02:01.052Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.686256092Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"1","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1792025-03-18T05:02:01.052Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.686300588Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"2","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1802025-03-18T05:02:01.052Z{"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-18T05:01:59.686912671Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"2","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1812025-03-18T05:02:01.052Z{"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-18T05:01:59.687070249Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"0","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1822025-03-18T05:02:01.052Z{"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-18T05:01:59.687123215Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"1","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1832025-03-18T05:02:01.052Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.68732107Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1842025-03-18T05:02:01.052Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687520564Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1852025-03-18T05:02:01.052Z{"msg":"[0]R flush_numbers: [1497, 1497, 1497, 1497, 1497]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687563081Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1862025-03-18T05:02:01.052Z{"msg":"[0]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687587429Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1872025-03-18T05:02:01.052Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687602238Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1882025-03-18T05:02:01.052Z{"msg":"[1]R flush_numbers: [1497, 1497, 1497, 1497, 1497]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687623616Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1892025-03-18T05:02:01.052Z{"msg":"[1]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687637585Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1902025-03-18T05:02:01.052Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687657743Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1912025-03-18T05:02:01.053Z{"msg":"[2]R flush_numbers: [1497, 1497, 1497, 1497, 1497]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687671333Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1922025-03-18T05:02:01.053Z{"msg":"[2]R generation: [25, 25, 25, 25, 25]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687691081Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1932025-03-18T05:02:01.053Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.68770816Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1942025-03-18T05:02:01.053Z{"msg":"Max found gen is 26","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687734978Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1952025-03-18T05:02:01.053Z{"msg":"Generation requested: 31 >= found:26","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687749567Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1962025-03-18T05:02:01.053Z{"msg":"Next flush: 1498","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687769505Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1972025-03-18T05:02:01.053Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687783034Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"":"downstairs","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
1982025-03-18T05:02:01.053Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO
1992025-03-18T05:02:01.053Z,"time":"2025-03-18T05:01:59.687802752Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
2002025-03-18T05:02:01.053Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687818401Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"0","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
2012025-03-18T05:02:01.053Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.68783515Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"1","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
2022025-03-18T05:02:01.053Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687852128Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"client":"2","":"downstairs","session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
2032025-03-18T05:02:01.053Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687870327Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
2042025-03-18T05:02:01.053Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687891896Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
2052025-03-18T05:02:01.054Z{"msg":"6a7e5255-ddd7-4b5a-8644-6c72d5ae7b2e is now active with session: 8ef8cb99-0818-4464-9b91-c30d4dc6a26c","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687905734Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
2062025-03-18T05:02:01.054Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687931422Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230,"session_id":"8ef8cb99-0818-4464-9b91-c30d4dc6a26c"}
2072025-03-18T05:02:01.054Z{"msg":"The guest has finished waiting for activation with:31","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687944341Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230}
2082025-03-18T05:02:01.054Z{"msg":"Activated sub_volume 6a7e5255-ddd7-4b5a-8644-6c72d5ae7b2e","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:01:59.687982089Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230}
2092025-03-18T05:02:01.054ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2102025-03-18T05:02:01.054ZFill test
2112025-03-18T05:02:01.087ZRead and Verify all blocks (0..50 range:false)
2122025-03-18T05:02:01.126ZWrote out file "/var/tmp/test_up-build/verify_file"
2132025-03-18T05:02:01.126ZCLIENT: Tests done. All submitted work has been ACK'd
2142025-03-18T05:02:01.126Z----------------------------------------------------------------
2152025-03-18T05:02:01.127Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:1
2162025-03-18T05:02:01.127ZStates: Active Active Active
2172025-03-18T05:02:01.127ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
2182025-03-18T05:02:01.130Z 1002 Acked Read 50 Done Done Done false
2192025-03-18T05:02:01.130Z STATES DS:0 DS:1 DS:2 TOTAL
2202025-03-18T05:02:01.130Z Sent 0 0 0 0
2212025-03-18T05:02:01.131Z Done 1 1 1 3
2222025-03-18T05:02:01.131Z Skipped 0 0 0 0
2232025-03-18T05:02:01.131Z Error 0 0 0 0
2242025-03-18T05:02:01.131ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
2252025-03-18T05:02:01.131ZDownstairs last five completed: 1001 1000
2262025-03-18T05:02:01.131ZUpstairs last five completed: 1002 1001 1000
2272025-03-18T05:02:01.131ZCLIENT: Up:0 ds:1 act:3
2282025-03-18T05:02:05.128Z----------------------------------------------------------------
2292025-03-18T05:02:05.128Z Crucible gen:31 GIO:true work queues: Upstairs:0 downstairs:0
2302025-03-18T05:02:05.128ZDownstairs last five completed: 1003 1002 1001 1000
2312025-03-18T05:02:05.128ZUpstairs last five completed: 1003 1002 1001 1000
2322025-03-18T05:02:05.128ZCLIENT: Up:0 ds:0 act:3
2332025-03-18T05:02:05.128ZCLIENT: All crucible jobs finished, exiting program
2342025-03-18T05:02:05.132Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-03-18T05:02:03.768150803Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1230}
2352025-03-18T05:02:05.138ZRepair setup passed
2362025-03-18T05:02:05.142ZCopy the region for /var/tmp/test_up-build/8830
2372025-03-18T05:02:05.145Zcp -r /var/tmp/test_up-build/8830 /var/tmp/test_up-build/previous
2382025-03-18T05:02:05.148Z/var/tmp/bins/crutest fill -g 32 -q --key QUdMCMAgZhw5pa+L+eeMc37iRhk+etMJJKLhh5Gxz+8= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
2392025-03-18T05:02:05.203Z{"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-18T05:02:03.842871361Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"task":"crutest"}
2402025-03-18T05:02:05.207Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.843422829Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"task":"crutest"}
2412025-03-18T05:02:05.207Z{"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-18T05:02:03.845134556Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"task":"crutest"}
2422025-03-18T05:02:05.207Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.84534221Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236}
2432025-03-18T05:02:05.207Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"15e44c06f41a7116c9cfd33f9c32fc1c3d097c63\",\n git_commit_timestamp: \"2025-03-18T04:42:20.000000000Z\",\n git_branch: \"renovate/anyhow-1.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-18T05:02:03.845392016Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236}
2442025-03-18T05:02:05.207Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.845417154Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236}
2452025-03-18T05:02:05.207Z{"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-18T05:02:03.845432503Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236}
2462025-03-18T05:02:05.207Z{"msg":"Crucible 22f42e84-3db6-4f0e-ba98-df582d0e57c6 has session id: 60c4cb5a-3be0-4d37-aad5-0be17ef204a0","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.846026387Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2472025-03-18T05:02:05.207Z{"msg":"Upstairs opts: Upstairs UUID: 22f42e84-3db6-4f0e-ba98-df582d0e57c6, 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-18T05:02:03.846073093Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2482025-03-18T05:02:05.207Z{"msg":"Crucible stats registered with UUID: 22f42e84-3db6-4f0e-ba98-df582d0e57c6","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.846091772Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2492025-03-18T05:02:05.207Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-03-18T05:02:03.846105711Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2502025-03-18T05:02:05.215Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.847228024Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"task":"crutest"}
2512025-03-18T05:02:05.215Z{"msg":"The guest has requested activation with gen:32","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.847307018Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236}
2522025-03-18T05:02:05.215Z{"msg":"22f42e84-3db6-4f0e-ba98-df582d0e57c6 active request set","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.847351034Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2532025-03-18T05:02:05.215Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.847395831Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"0","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2542025-03-18T05:02:05.215Z{"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-18T05:02:03.847470115Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"0","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2552025-03-18T05:02:05.215Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.847523371Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"1","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2562025-03-18T05:02:05.215Z{"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-18T05:02:03.847575487Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"1","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2572025-03-18T05:02:05.215Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.847601655Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"2","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2582025-03-18T05:02:05.215Z{"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-18T05:02:03.847634083Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"2","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2592025-03-18T05:02:05.215Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.84766748Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"io task","client":"2","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2602025-03-18T05:02:05.215Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.847703157Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"io task","client":"0","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2612025-03-18T05:02:05.215Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.847949598Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"io task","client":"1","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2622025-03-18T05:02:05.215Z{"msg":"ds_connection connected from Ok(127.0.0.1:37090)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.847992085Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"io task","client":"0","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2632025-03-18T05:02:05.215Z{"msg":"ds_connection connected from Ok(127.0.0.1:37345)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.848033292Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"io task","client":"1","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2642025-03-18T05:02:05.215Z{"msg":"ds_connection connected from Ok(127.0.0.1:59497)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.84806261Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"io task","client":"2","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2652025-03-18T05:02:05.215Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.848550522Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"1","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2662025-03-18T05:02:05.215Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.848609507Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"2","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2672025-03-18T05:02:05.215Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.848629566Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"0","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2682025-03-18T05:02:05.215Z{"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-18T05:02:03.849401816Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"2","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2692025-03-18T05:02:05.215Z{"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-18T05:02:03.849624829Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"1","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2702025-03-18T05:02:05.216Z{"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-18T05:02:03.849679684Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"0","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2712025-03-18T05:02:05.216Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.849896288Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2722025-03-18T05:02:05.216Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.85012346Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2732025-03-18T05:02:05.216Z{"msg":"[0]R flush_numbers: [1498, 1498, 1498, 1498, 1498]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850201264Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2742025-03-18T05:02:05.216Z{"msg":"[0]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850245391Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2752025-03-18T05:02:05.216Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850298786Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2762025-03-18T05:02:05.216Z{"msg":"[1]R flush_numbers: [1498, 1498, 1498, 1498, 1498]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850349982Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2772025-03-18T05:02:05.216Z{"msg":"[1]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850400279Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2782025-03-18T05:02:05.216Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850451545Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2792025-03-18T05:02:05.216Z{"msg":"[2]R flush_numbers: [1498, 1498, 1498, 1498, 1498]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850500211Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2802025-03-18T05:02:05.216Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850557406Z","hostnameWait for a query_work_queue command to finish before sending IO
2812025-03-18T05:02:05.216Z":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2822025-03-18T05:02:05.216Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850611022Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2832025-03-18T05:02:05.216Z{"msg":"Max found gen is 32","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.85064168Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2842025-03-18T05:02:05.216Z{"msg":"Generation requested: 32 >= found:32","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850682627Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2852025-03-18T05:02:05.216Z{"msg":"Next flush: 1499","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850716724Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2862025-03-18T05:02:05.216Z{"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850738663Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"":"downstairs","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2872025-03-18T05:02:05.216Z{"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850779359Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2882025-03-18T05:02:05.216Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850812017Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"0","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2892025-03-18T05:02:05.216Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850829076Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"1","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2902025-03-18T05:02:05.216Z{"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30Disk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
2912025-03-18T05:02:05.216Z,"time":"2025-03-18T05:02:03.850875842Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"client":"2","":"downstairs","session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2922025-03-18T05:02:05.216Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850908599Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2932025-03-18T05:02:05.216Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850922428Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2942025-03-18T05:02:05.216Z{"msg":"22f42e84-3db6-4f0e-ba98-df582d0e57c6 is now active with session: 60c4cb5a-3be0-4d37-aad5-0be17ef204a0","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850949196Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2952025-03-18T05:02:05.216Z{"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850969115Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236,"session_id":"60c4cb5a-3be0-4d37-aad5-0be17ef204a0"}
2962025-03-18T05:02:05.216Z{"msg":"The guest has finished waiting for activation with:32","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.850994383Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236}
2972025-03-18T05:02:05.216Z{"msg":"Activated sub_volume 22f42e84-3db6-4f0e-ba98-df582d0e57c6","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:03.851007002Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236}
2982025-03-18T05:02:05.216ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
2992025-03-18T05:02:05.216ZFill test
3002025-03-18T05:02:05.250ZRead and Verify all blocks (0..50 range:false)
3012025-03-18T05:02:05.289ZWrote out file "/var/tmp/test_up-build/verify_file"
3022025-03-18T05:02:05.289ZCLIENT: Tests done. All submitted work has been ACK'd
3032025-03-18T05:02:05.293Z----------------------------------------------------------------
3042025-03-18T05:02:05.293Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:1
3052025-03-18T05:02:05.294ZStates: Active Active Active
3062025-03-18T05:02:05.294ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
3072025-03-18T05:02:05.294Z 1002 Acked Read 50 Sent Sent Done false
3082025-03-18T05:02:05.294Z STATES DS:0 DS:1 DS:2 TOTAL
3092025-03-18T05:02:05.294Z Sent 1 1 0 2
3102025-03-18T05:02:05.294Z Done 0 0 1 1
3112025-03-18T05:02:05.294Z Skipped 0 0 0 0
3122025-03-18T05:02:05.294Z Error 0 0 0 0
3132025-03-18T05:02:05.294ZLast Flush: Some(JobId(1001)) Some(JobId(1001)) Some(JobId(1001))
3142025-03-18T05:02:05.294ZDownstairs last five completed: 1001 1000
3152025-03-18T05:02:05.294ZUpstairs last five completed: 1002 1001 1000
3162025-03-18T05:02:05.294ZCLIENT: Up:0 ds:1 act:3
3172025-03-18T05:02:09.292Z----------------------------------------------------------------
3182025-03-18T05:02:09.292Z Crucible gen:32 GIO:true work queues: Upstairs:0 downstairs:0
3192025-03-18T05:02:09.292ZDownstairs last five completed: 1003 1002 1001 1000
3202025-03-18T05:02:09.292ZUpstairs last five completed: 1003 1002 1001 1000
3212025-03-18T05:02:09.292ZCLIENT: Up:0 ds:0 act:3
3222025-03-18T05:02:09.292ZCLIENT: All crucible jobs finished, exiting program
3232025-03-18T05:02:09.299Z{"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2025-03-18T05:02:07.930447522Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1236}
3242025-03-18T05:02:09.306ZRepair part 1 passed
3252025-03-18T05:02:09.306Z
3262025-03-18T05:02:09.306ZKill the current downstairs
3272025-03-18T05:02:09.472ZDownstairs 2 stopped
3282025-03-18T05:02:09.472Zmv /var/tmp/test_up-build/8830 /var/tmp/test_up-build/new
3292025-03-18T05:02:09.475ZNow put back the original so we have a mismatch
3302025-03-18T05:02:09.475Zmv /var/tmp/test_up-build/previous /var/tmp/test_up-build/8830
3312025-03-18T05:02:09.478ZRestart downstairs with old directory
3322025-03-18T05:02:09.536Z/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
3332025-03-18T05:02:09.555ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
3342025-03-18T05:02:09.559Z 0 000-009 32 32 31 1499 1499 1498 F F F <---
3352025-03-18T05:02:09.559Z 1 010-019 32 32 31 1499 1499 1498 F F F <---
3362025-03-18T05:02:09.559Z 2 020-029 32 32 31 1499 1499 1498 F F F <---
3372025-03-18T05:02:09.559Z 3 030-039 32 32 31 1499 1499 1498 F F F <---
3382025-03-18T05:02:09.560Z 4 040-049 32 32 31 1499 1499 1498 F F F <---
3392025-03-18T05:02:09.560ZMax gen: 32, Max flush: 1499
3402025-03-18T05:02:09.782ZError: Difference in extent metadata found!
3412025-03-18T05:02:09.782Z
3422025-03-18T05:02:09.782ZStack backtrace:
3432025-03-18T05:02:09.782Z 0: anyhow::error::<impl anyhow::Error>::msg
3442025-03-18T05:02:09.782Z at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.97/src/backtrace.rs:27:14
3452025-03-18T05:02:09.782Z 1: anyhow::__private::format_err
3462025-03-18T05:02:09.782Z at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.97/src/lib.rs:692:13
3472025-03-18T05:02:09.803Zdump test found error as expected
3482025-03-18T05:02:09.808Z
3492025-03-18T05:02:09.808Z
3502025-03-18T05:02:09.808Z/var/tmp/bins/crutest verify --range -g 33 -q --key QUdMCMAgZhw5pa+L+eeMc37iRhk+etMJJKLhh5Gxz+8= --dsc 127.0.0.1:9998 --verify-out /var/tmp/test_up-build/verify_file --verify-in /var/tmp/test_up-build/verify_file
3512025-03-18T05:02:09.862Z{"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-18T05:02:08.500773717Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"task":"crutest"}
3522025-03-18T05:02:09.867Z{"msg":"dsc has 3 regions. This means 1 sub_volumes","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.501327274Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"task":"crutest"}
3532025-03-18T05:02:09.867Z{"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-18T05:02:08.503079848Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"task":"crutest"}
3542025-03-18T05:02:09.867Z{"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.50331097Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244}
3552025-03-18T05:02:09.867Z{"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"15e44c06f41a7116c9cfd33f9c32fc1c3d097c63\",\n git_commit_timestamp: \"2025-03-18T04:42:20.000000000Z\",\n git_branch: \"renovate/anyhow-1.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-18T05:02:08.503357047Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244}
3562025-03-18T05:02:09.867Z{"msg":"Upstairs <-> Downstairs Message Version: 13","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.503373085Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244}
3572025-03-18T05:02:09.867Z{"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-18T05:02:08.503388274Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244}
3582025-03-18T05:02:09.867Z{"msg":"Crucible 2a226991-9a40-48cc-b3a6-23ae6d988cf2 has session id: d1efd850-fa4b-4478-abb8-21338bca258d","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.50408619Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3592025-03-18T05:02:09.867Z{"msg":"Upstairs opts: Upstairs UUID: 2a226991-9a40-48cc-b3a6-23ae6d988cf2, 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-18T05:02:08.504132387Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3602025-03-18T05:02:09.867Z{"msg":"Crucible stats registered with UUID: 2a226991-9a40-48cc-b3a6-23ae6d988cf2","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.504150625Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3612025-03-18T05:02:09.867Z{"msg":"could not find Downstairs address for Nexus","v":0,"name":"crucible","level":40,"time":"2025-03-18T05:02:08.504184123Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3622025-03-18T05:02:09.867Z{"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505165767Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"task":"crutest"}
3632025-03-18T05:02:09.867Z{"msg":"The guest has requested activation with gen:33","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505211603Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244}
3642025-03-18T05:02:09.867Z{"msg":"2a226991-9a40-48cc-b3a6-23ae6d988cf2 active request set","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505238081Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3652025-03-18T05:02:09.867Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.50526119Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"0","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3662025-03-18T05:02:09.867Z{"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-18T05:02:08.505317895Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"0","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3672025-03-18T05:02:09.867Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505361192Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"1","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3682025-03-18T05:02:09.867Z{"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-18T05:02:08.505403319Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"1","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3692025-03-18T05:02:09.868Z{"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505428057Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3702025-03-18T05:02:09.868Z{"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-18T05:02:08.505450855Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3712025-03-18T05:02:09.868Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505483302Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3722025-03-18T05:02:09.868Z{"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505519719Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"0","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3732025-03-18T05:02:09.868Z{"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505549037Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"1","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3742025-03-18T05:02:09.868Z{"msg":"ds_connection connected from Ok(127.0.0.1:54710)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505590174Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"0","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3752025-03-18T05:02:09.868Z{"msg":"ds_connection connected from Ok(127.0.0.1:52117)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505620842Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"1","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3762025-03-18T05:02:09.868Z{"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-18T05:02:08.505667448Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3772025-03-18T05:02:09.868Z{"msg":"client task is sending Done(ConnectionFailed(Os { code: 146, kind: ConnectionRefused, message: \"Connection refused\" }))","v":0,"name":"crucible","level":40,"time":"2025-03-18T05:02:08.505725843Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3782025-03-18T05:02:09.868Z{"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-18T05:02:08.50577192Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3792025-03-18T05:02:09.868Z{"msg":"client task is exiting","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.505807567Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3802025-03-18T05:02:09.871Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.506270421Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"1","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3812025-03-18T05:02:09.871Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.506320297Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"0","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3822025-03-18T05:02:09.871Z{"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-18T05:02:08.506764523Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"0","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3832025-03-18T05:02:09.871Z{"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-18T05:02:08.506889813Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"1","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3842025-03-18T05:02:09.871Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.507151223Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3852025-03-18T05:02:09.871Z{"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:08.507200199Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3862025-03-18T05:02:19.869Z{"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.507021149Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3872025-03-18T05:02:19.869Z{"msg":"ds_connection connected from Ok(127.0.0.1:64274)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.50714036Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"io task","client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3882025-03-18T05:02:19.875Z{"msg":"version negotiation from state Connecting { state: WaitForPromote, mode: New }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.508205407Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3892025-03-18T05:02:19.875Z{"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-18T05:02:18.508842998Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3902025-03-18T05:02:19.875Z{"msg":"[0]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509260686Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3912025-03-18T05:02:19.875Z{"msg":"[0]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509295723Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3922025-03-18T05:02:19.875Z{"msg":"[0]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509315092Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3932025-03-18T05:02:19.875Z{"msg":"[1]R flush_numbers: [1499, 1499, 1499, 1499, 1499]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509349789Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3942025-03-18T05:02:19.875Z{"msg":"[1]R generation: [32, 32, 32, 32, 32]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509382846Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3952025-03-18T05:02:19.875Z{"msg":"[1]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509416264Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3962025-03-18T05:02:19.875Z{"msg":"[2]R flush_numbers: [1498, 1498, 1498, 1498, 1498]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509434432Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3972025-03-18T05:02:19.875Z{"msg":"[2]R generation: [31, 31, 31, 31, 31]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509451791Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3982025-03-18T05:02:19.875Z{"msg":"[2]R dirty: [false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509480879Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
3992025-03-18T05:02:19.875Z{"msg":"Max found gen is 33","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509495898Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4002025-03-18T05:02:19.875Z{"msg":"Generation requested: 33 >= found:33","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509527525Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4012025-03-18T05:02:19.875Z{"msg":"Next flush: 1500","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509544664Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4022025-03-18T05:02:19.875Z{"msg":"extent 0 needs reconciliation: ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 31, flush: 1498, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509571932Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4032025-03-18T05:02:19.875Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 31, flush: 1498, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509610129Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4042025-03-18T05:02:19.875Z{"msg":"found dest for source 0 for extent at index 0 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509630277Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4052025-03-18T05:02:19.875Z{"msg":"extent 1 needs reconciliation: ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 31, flush: 1498, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509646586Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4062025-03-18T05:02:19.875Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 31, flush: 1498, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509662955Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4072025-03-18T05:02:19.875Z{"msg":"found dest for source 0 for extent at index 1 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509695352Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4082025-03-18T05:02:19.875Z{"msg":"extent 2 needs reconciliation: ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 31, flush: 1498, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.50972018Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4092025-03-18T05:02:19.875Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 31, flush: 1498, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509751858Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4102025-03-18T05:02:19.875Z{"msg":"found dest for source 0 for extent at index 2 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509783345Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4112025-03-18T05:02:19.875Z{"msg":"extent 3 needs reconciliation: ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 31, flush: 1498, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509810713Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4122025-03-18T05:02:19.876Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 31, flush: 1498, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509868269Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4132025-03-18T05:02:19.876Z{"msg":"found dest for source 0 for extent at index 3 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509905646Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4142025-03-18T05:02:19.876Z{"msg":"extent 4 needs reconciliation: ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 32, flush: 1499, dirty: false } ExtentMetadata { gen: 31, flush: 1498, dirty: false }","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509926654Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4152025-03-18T05:02:19.876Z{"msg":"extent:0 [ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 32, flush: 1499, dirty: false }, ExtentMetadata { gen: 31, flush: 1498, dirty: false }] => 0","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509950683Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4162025-03-18T05:02:19.876Z{"msg":"found dest for source 0 for extent at index 4 => [ClientId(2)]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509965901Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"mend","":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4172025-03-18T05:02:19.876Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.509993029Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"0","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4182025-03-18T05:02:19.876Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.510016637Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"1","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4192025-03-18T05:02:19.876Z{"msg":"Transition from Connecting { state: WaitQuorum, mode: New } to Reconcile","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.510032416Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4202025-03-18T05:02:19.876Z{"msg":"Full repair list: {ExtentId(1): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(3): ExtentFix { source: ClientId(0), dest: [ClientId(2)] }, ExtentId(4): 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)] }}","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.510052824Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4212025-03-18T05:02:19.876Z{"msg":"Task list: [ReconcileIO { id: ReconciliationId(0), op: ExtentFlush { repair_id: ReconciliationId(0), extent_id: ExtentId(1), client_id: ClientId(0), flush_number: 1500, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(1), op: ExtentClose { repair_id: ReconciliationId(1), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(2), op: ExtentRepair { repair_id: ReconciliationId(2), extent_id: ExtentId(1), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(3), op: ExtentReopen { repair_id: ReconciliationId(3), extent_id: ExtentId(1) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(4), op: ExtentFlush { repair_id: ReconciliationId(4), extent_id: ExtentId(3), client_id: ClientId(0), flush_number: 1500, 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(4), client_id: ClientId(0), flush_number: 1500, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(9), op: ExtentClose { repair_id: ReconciliationId(9), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(10), op: ExtentRepair { repair_id: ReconciliationId(10), 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(11), op: ExtentReopen { repair_id: ReconciliationId(11), extent_id: ExtentId(4) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(12), op: ExtentFlush { repair_id: ReconciliationId(12), extent_id: ExtentId(0), client_id: ClientId(0), flush_number: 1500, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(13), op: ExtentClose { repair_id: ReconciliationId(13), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(14), op: ExtentRepair { repair_id: ReconciliationId(14), extent_id: ExtentId(0), source_client_id: ClientId(0), source_repair_address: 0.0.0.0:12810, dest_clients: [ClientId(2)] }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(15), op: ExtentReopen { repair_id: ReconciliationId(15), extent_id: ExtentId(0) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(16), op: ExtentFlush { repair_id: ReconciliationId(16), extent_id: ExtentId(2), client_id: ClientId(0), flush_number: 1500, gen_number: 33 }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(17), op: ExtentClose { repair_id: ReconciliationId(17), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }, ReconcileIO { id: ReconciliationId(18), op: ExtentRepair { repair_id: ReconciliationId(18), 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(19), op: ExtentReopen { repair_id: ReconciliationId(19), extent_id: ExtentId(2) }, state: ClientData([New, New, New]) }]","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.510138818Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4222025-03-18T05:02:19.876Z{"msg":"starting reconciliation fe696d45-7476-482b-a980-75ae7cf729f1: found 20 extents that need repair","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.510158856Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4232025-03-18T05:02:19.876Z{"msg":"sending reconcile request ReconciliationId(2)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.510172965Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4242025-03-18T05:02:19.884Z{"msg":"sending reconcile request ReconciliationId(6)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.519963168Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4252025-03-18T05:02:19.887Z{"msg":"sending reconcile request ReconciliationId(10)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.523761134Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4262025-03-18T05:02:19.893Z{"msg":"sending reconcile request ReconciliationId(14)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.527670001Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4272025-03-18T05:02:19.897Z{"msg":"sending reconcile request ReconciliationId(18)","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.531249975Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4282025-03-18T05:02:19.897Z{"msg":"done with reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.534329626Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"":"downstairs","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4292025-03-18T05:02:19.897Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.534367873Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"0","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4302025-03-18T05:02:19.897Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.534384492Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"1","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4312025-03-18T05:02:19.897Z{"msg":"Transition from Reconcile to Active","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.53440622Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"client":"2","":"downstairs","session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4322025-03-18T05:02:19.897Z{"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.534427539Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4332025-03-18T05:02:19.897Z{"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.534440658Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4342025-03-18T05:02:19.897Z{"msg":"2a226991-9a40-48cc-b3a6-23ae6d988cf2 is now active with session: d1efd850-fa4b-4478-abb8-21338bca258d","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.534460586Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244,"session_id":"d1efd850-fa4b-4478-abb8-21338bca258d"}
4352025-03-18T05:02:19.897Z{"msg":"The guest has finished waiting for activation with:33","v":0,"name":"crucible","level":30,"time":"2025-03-18T05:02:18.534473735Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244}
4362025-03-18T05:02:19.897Z{"msg":"Activated sub_volume 2a226991-9a40-48cc-b3a6-23ae6d988cf2","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO
4372025-03-18T05:02:19.897Z,"time":"2025-03-18T05:02:18.534485414Z","hostname":"w-01JPKST5XC2HZ2QYN8PJ049NF1","pid":1244}
4382025-03-18T05:02:19.897ZDisk: sv:1 bs:4096 ts:204800 tb:50 max_io:50 or 204800
4392025-03-18T05:02:19.902ZLoading write count information from file "/var/tmp/test_up-build/verify_file"
4402025-03-18T05:02:19.902ZRead and Verify all blocks (0..50 range:true)
4412025-03-18T05:02:19.936ZWrote out file "/var/tmp/test_up-build/verify_file"
4422025-03-18T05:02:19.936ZVerify test completed
4432025-03-18T05:02:19.941ZWrote out file "/var/tmp/test_up-build/verify_file"
4442025-03-18T05:02:19.941ZCLIENT: Tests done. All submitted work has been ACK'd
4452025-03-18T05:02:19.941Z----------------------------------------------------------------
4462025-03-18T05:02:19.941Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:1
4472025-03-18T05:02:19.941ZStates: Active Active Active
4482025-03-18T05:02:19.941ZJOBID ACK TYPE BKS/EXT DS:0 DS:1 DS:2 REPLAY
4492025-03-18T05:02:19.941Z 1000 Acked Read 50 Done Done Done false
4502025-03-18T05:02:19.941Z STATES DS:0 DS:1 DS:2 TOTAL
4512025-03-18T05:02:19.941Z Sent 0 0 0 0
4522025-03-18T05:02:19.941Z Done 1 1 1 3
4532025-03-18T05:02:19.941Z Skipped 0 0 0 0
4542025-03-18T05:02:19.941Z Error 0 0 0 0
4552025-03-18T05:02:19.942ZLast Flush: None None None
4562025-03-18T05:02:19.942ZDownstairs last five completed:
4572025-03-18T05:02:19.942ZUpstairs last five completed: 1000
4582025-03-18T05:02:19.942ZCLIENT: Up:0 ds:1 act:3
4592025-03-18T05:02:23.939Z----------------------------------------------------------------
4602025-03-18T05:02:23.939Z Crucible gen:33 GIO:true work queues: Upstairs:0 downstairs:0
4612025-03-18T05:02:23.939ZDownstairs last five completed: 1001 1000
4622025-03-18T05:02:23.939ZUpstairs last five completed: 1001 1000
4632025-03-18T05:02:23.939ZCLIENT: Up:0 ds:0 act:3
4642025-03-18T05:02:23.939ZCLIENT: All crucible jobs finished, exiting program
4652025-03-18T05:02:23.945ZRepair part 2 passed
4662025-03-18T05:02:23.948Z/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
4672025-03-18T05:02:23.962ZEXT BLOCKS GEN0 GEN1 GEN2 FL0 FL1 FL2 D0 D1 D2 DIFF
4682025-03-18T05:02:23.962Z 0 000-009 32 32 32 1499 1499 1499 F F F
4692025-03-18T05:02:23.962Z 1 010-019 32 32 32 1499 1499 1499 F F F
4702025-03-18T05:02:23.962Z 2 020-029 32 32 32 1499 1499 1499 F F F
4712025-03-18T05:02:23.962Z 3 030-039 32 32 32 1499 1499 1499 F F F
4722025-03-18T05:02:23.962Z 4 040-049 32 32 32 1499 1499 1499 F F F
4732025-03-18T05:02:23.966ZMax gen: 32, Max flush: 1499
4742025-03-18T05:02:23.969Zdump test passed
4752025-03-18T05:02:23.969Z/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
4762025-03-18T05:02:23.983Z Extent 1
4772025-03-18T05:02:23.983ZGEN 32 32 32
4782025-03-18T05:02:23.983ZFLUSH_ID 1499 1499 1499
4792025-03-18T05:02:23.983ZDIRTY
4802025-03-18T05:02:23.983Z
4812025-03-18T05:02:23.983ZBLOCK D0 D1 D2 C0 C1 C2 DIFF
4822025-03-18T05:02:23.987Z010 A A A A A A
4832025-03-18T05:02:23.987Z011 A A A A A A
4842025-03-18T05:02:23.991Z012 A A A A A A
4852025-03-18T05:02:23.991Z013 A A A A A A
4862025-03-18T05:02:23.991Z014 A A A A A A
4872025-03-18T05:02:23.994Z015 A A A A A A
4882025-03-18T05:02:23.994Z016 A A A A A A
4892025-03-18T05:02:23.998Z017 A A A A A A
4902025-03-18T05:02:23.998Z018 A A A A A A
4912025-03-18T05:02:24.001Z019 A A A A A A
4922025-03-18T05:02:24.005Zdump extent test passed
4932025-03-18T05:02:24.005Z/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
4942025-03-18T05:02:24.018ZExtent 2 Block in extent 0 Actual block 20
4952025-03-18T05:02:24.018Z
4962025-03-18T05:02:24.022Z DATA SHA256 VER
4972025-03-18T05:02:24.022Z------ ---------------------------------------------------------------- ---
4982025-03-18T05:02:24.022Z 0 7dbd7b0b90cbc2e68b0157edeed441c5e833c8ebdb67c2f8ff9e59935d21a67d A
4992025-03-18T05:02:24.022Z 1 7dbd7b0b90cbc2e68b0157edeed441c5e833c8ebdb67c2f8ff9e59935d21a67d A
5002025-03-18T05:02:24.022Z 2 7dbd7b0b90cbc2e68b0157edeed441c5e833c8ebdb67c2f8ff9e59935d21a67d A
5012025-03-18T05:02:24.022Z
5022025-03-18T05:02:24.022ZNONCES 0 1 2 DIFF
5032025-03-18T05:02:24.022Z------ ------------------------ ------------------------ ------------------------ -----
5042025-03-18T05:02:24.022Z 0 0708388fd728f6c041120edb 0708388fd728f6c041120edb 0708388fd728f6c041120edb
5052025-03-18T05:02:24.022Z
5062025-03-18T05:02:24.022Z TAGS 0 1 2 DIFF
5072025-03-18T05:02:24.022Z------ -------------------------------- -------------------------------- -------------------------------- -----
5082025-03-18T05:02:24.022Z 0 8242c261834129aa63002141a916c205 8242c261834129aa63002141a916c205 8242c261834129aa63002141a916c205
5092025-03-18T05:02:24.022Z
5102025-03-18T05:02:24.022ZHASHES 0 1 2 DIFF
5112025-03-18T05:02:24.022Z------ ---------------- ---------------- ---------------- -----
5122025-03-18T05:02:24.022Z
5132025-03-18T05:02:24.026Zdump block test passed
5142025-03-18T05:02:24.026ZInitial upstairs tests have completed, stopping all downstairs
5152025-03-18T05:02:29.092ZCreating 4 larger downstairs regions
5162025-03-18T05:02:29.214ZStarting 4 downstairs
5172025-03-18T05:02:34.222Zdsc restarted at PID: 1257
5182025-03-18T05:02:34.458ZNow do the replace-reconcile test
5192025-03-18T05:02:34.515ZUsing 8840 for the replacement port
5202025-03-18T05:05:41.050ZCompleted test: replace-reconcile
5212025-03-18T05:05:41.054ZNow do the replace-before-active test
5222025-03-18T05:08:47.572ZCompleted test: replace-before-active
5232025-03-18T05:08:47.575ZAll tests have completed, stopping all downstairs
5242025-03-18T05:08:47.630Z
5252025-03-18T05:08:47.631ZAll Tests have passed
5262025-03-18T05:08:47.634Z10:06 Test duration
5272025-03-18T05:08:47.634Z
5282025-03-18T05:08:47.634Zreal 10:05.551985615
5292025-03-18T05:08:47.634Zuser 6:25.423718307
5302025-03-18T05:08:47.634Zsys 12.278119816
5312025-03-18T05:08:47.634Ztrap 0.198012733
5322025-03-18T05:08:47.634Ztflt 0.022376603
5332025-03-18T05:08:47.634Zdflt 0.014676670
5342025-03-18T05:08:47.634Zkflt 0.001743703
5352025-03-18T05:08:47.634Zlock 8:31:47.714833742
5362025-03-18T05:08:47.634Zslp 34:15.458157010
5372025-03-18T05:08:47.634Zlat 23.763268632
5382025-03-18T05:08:47.634Zstop 0.132924465
5392025-03-18T05:08:47.634Z+ echo 'test-up-encrypted ends'
5402025-03-18T05:08:47.634Ztest-up-encrypted ends
5412025-03-18T05:08:52.636Zprocess exited: duration 614023 ms, exit code 0
5422025-03-18T05:08:52.636Zexec warning: : stdio descriptors remain open after task exit; waiting 60 seconds for them to close
5432025-03-18T05:09:52.678Zexec warning: : stdout descriptor may be held open by a background process; giving up!
5442025-03-18T05:09:52.678Zexec warning: : stderr descriptor may be held open by a background process; giving up!
 
5452025-03-18T05:09:52.690Zfound 14 output files
5462025-03-18T05:09:52.690Zuploading: /tmp/test_up-build/dsc-out.txt (41718 bytes)
5472025-03-18T05:09:53.707Zuploaded: /tmp/test_up-build/dsc-out.txt
5482025-03-18T05:09:53.707Zuploading: /tmp/test_up-build/test_up_out.txt (7627360 bytes)
5492025-03-18T05:09:54.800Zuploaded: /tmp/test_up-build/test_up_out.txt
5502025-03-18T05:09:54.803Zuploading: /tmp/test_up-build/dsc/downstairs-8810.txt (2504 bytes)
5512025-03-18T05:09:55.811Zuploaded: /tmp/test_up-build/dsc/downstairs-8810.txt
5522025-03-18T05:09:55.816Zuploading: /tmp/test_up-build/dsc/downstairs-8820.txt (144648 bytes)
5532025-03-18T05:09:56.828Zuploaded: /tmp/test_up-build/dsc/downstairs-8820.txt
5542025-03-18T05:09:56.828Zuploading: /tmp/test_up-build/dsc/downstairs-8830.txt (251035 bytes)
5552025-03-18T05:09:57.846Zuploaded: /tmp/test_up-build/dsc/downstairs-8830.txt
5562025-03-18T05:09:57.849Zuploading: /tmp/test_up-build/dsc/downstairs-8840.txt (139436 bytes)
5572025-03-18T05:09:58.861Zuploaded: /tmp/test_up-build/dsc/downstairs-8840.txt
5582025-03-18T05:09:58.864Zuploading: /tmp/debug/df.txt (1270 bytes)
5592025-03-18T05:09:59.872Zuploaded: /tmp/debug/df.txt
5602025-03-18T05:09:59.875Zuploading: /tmp/debug/dtrace.txt (541115 bytes)
5612025-03-18T05:10:00.892Zuploaded: /tmp/debug/dtrace.txt
5622025-03-18T05:10:00.892Zuploading: /tmp/debug/iostat.txt (199994 bytes)
5632025-03-18T05:10:00.903Zupload warning: file "/tmp/debug/iostat.txt" changed size mid upload: 199994 -> 202378
5642025-03-18T05:10:01.910Zuploaded: /tmp/debug/iostat.txt
5652025-03-18T05:10:01.910Zuploading: /tmp/debug/mpstat.txt (487822 bytes)
5662025-03-18T05:10:01.924Zupload warning: file "/tmp/debug/mpstat.txt" changed size mid upload: 487822 -> 494365
5672025-03-18T05:10:02.931Zuploaded: /tmp/debug/mpstat.txt
5682025-03-18T05:10:02.934Zuploading: /tmp/debug/paging.txt (86567 bytes)
5692025-03-18T05:10:02.940Zupload warning: file "/tmp/debug/paging.txt" changed size mid upload: 86567 -> 87855
5702025-03-18T05:10:03.947Zuploaded: /tmp/debug/paging.txt
5712025-03-18T05:10:03.950Zuploading: /tmp/debug/prstat.txt (937798 bytes)
5722025-03-18T05:10:03.964Zupload warning: file "/tmp/debug/prstat.txt" changed size mid upload: 937798 -> 952011
5732025-03-18T05:10:04.971Zuploaded: /tmp/debug/prstat.txt
5742025-03-18T05:10:04.971Zuploading: /tmp/debug/psrinfo.txt (1528 bytes)
5752025-03-18T05:10:05.981Zuploaded: /tmp/debug/psrinfo.txt
5762025-03-18T05:10:05.981Zuploading: /tmp/debug/upstairs-info.txt (69960 bytes)
5772025-03-18T05:10:06.995Zuploaded: /tmp/debug/upstairs-info.txt