01M6PTTNSCAKW93MS72SE8ZVV2: phd-run-migrate-from-base

BasicConfig {
    output_rules: [
        "/tmp/phd-runner.log",
        "/tmp/phd-tmp-files.tar.gz",
    ],
    rust_toolchain: None,
    target: Some(
        "lab-3.0-gimlet",
    ),
    access_repos: [],
    publish: [],
    skip_clone: true,
}

Buildomat Job: 01M6PTV8FYBABZDSWTRTMDBR4C

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-11-05T21:57:17.199Zjob dependencies complete; ready to run (waiting for 10 m 37 s)
22026-11-05T22:48:15.533Zjob assigned to worker 01M6PY5WC10STPV84J2CCBPN0B [factory edgar, gimlet/BRM42220060/1474] (queued for 50 m 58 s)
32026-11-05T22:48:16.539Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-11-05T22:48:16.657Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-11-05T22:48:16.657Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-11-05T22:48:16.711Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-11-05T22:48:16.711Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-11-05T22:48:25.539Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-11-05T22:48:25.539Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-11-05T22:48:25.602Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-11-05T22:48:25.602Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-11-05T22:48:46.186Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-11-05T22:48:46.187Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-11-05T22:49:02.115Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-11-05T22:49:02.115Zstarting task 0: "setup"
162026-11-05T22:49:02.139Z++ uname -s
172026-11-05T22:49:02.139Z+ kern=SunOS
182026-11-05T22:49:02.139Z+ build_user=build
192026-11-05T22:49:02.139Z+ build_uid=12345
202026-11-05T22:49:02.139Z+ work_dir=/work
212026-11-05T22:49:02.140Z+ input_dir=/input
222026-11-05T22:49:02.140Z+ [[ 0 == 12345 ]]
232026-11-05T22:49:02.140Z+ case "$kern" in
242026-11-05T22:49:02.140Z+ groupadd -g 12345 build
252026-11-05T22:49:02.142Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-11-05T22:49:04.154Z+ zfs create -o mountpoint=/work rpool/work
272026-11-05T22:49:04.343Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-11-05T22:49:04.373Z+ home_fs=
292026-11-05T22:49:04.373Z+ [[ '' == autofs ]]
302026-11-05T22:49:04.373Z+ mkdir -p /home/build
312026-11-05T22:49:04.373Z+ chown build:build /home/build /work
322026-11-05T22:49:06.354Z+ chmod 0700 /home/build /work
332026-11-05T22:49:06.379Zprocess exited: duration 4243 ms, exit code 0
 
342026-11-05T22:49:06.443Zstarting task 1: "authentication"
352026-11-05T22:49:06.524Zprocess exited: duration 70 ms, exit code 0
 
362026-11-05T22:49:06.575Zstarting task 2: "build"
372026-11-05T22:49:06.601Z+ indir=/input
382026-11-05T22:49:06.601Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-11-05T22:49:06.601Z+ phddir=/work/phd-test
402026-11-05T22:49:06.601Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-11-05T22:49:06.634Z++ pilot local disk list -H -o type,disk
422026-11-05T22:49:06.634Z++ grep -v M.2
432026-11-05T22:49:06.635Z++ cut -f 2
442026-11-05T22:49:06.706Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC586d0 c9t0014EE81000BC57Cd0 c10t0014EE81000BC3CCd0 c11t0014EE81000BC478d0 c4t0014EE81000BC5BBd0 c3t0014EE81000BC247d0 c2t0014EE81000BC649d0 c6t0014EE81000BC634d0 c5t0014EE81000BC0B1d0
452026-11-05T22:49:09.188Z+ artifactdir=/phd-artifacts
462026-11-05T22:49:09.188Z+ banner Inputs
472026-11-05T22:49:09.265Z ###
482026-11-05T22:49:09.265Z # # # ##### # # ##### ####
492026-11-05T22:49:09.265Z # ## # # # # # # #
502026-11-05T22:49:09.265Z # # # # # # # # # ####
512026-11-05T22:49:09.265Z # # # # ##### # # # #
522026-11-05T22:49:09.265Z # # ## # # # # # #
532026-11-05T22:49:09.265Z ### # # # #### # ####
542026-11-05T22:49:09.266Z
552026-11-05T22:49:09.266Z+ find /input -ls
562026-11-05T22:49:09.266Z 34 1 drwxr-xr-x 3 root root 3 Nov 5 22:48 /input
572026-11-05T22:49:09.266Z 2 1 drwxr-xr-x 3 root root 3 Nov 5 22:48 /input/phd-build
582026-11-05T22:49:09.266Z 3 2 drwxr-xr-x 2 root root 8 Nov 5 22:48 /input/phd-build/out
592026-11-05T22:49:09.266Z 512 216850 -rw-r--r-- 1 root root 221912196 Nov 5 22:49 /input/phd-build/out/propolis-tests-debug.tar.gz
602026-11-05T22:49:09.266Z 130 192193 -rw-r--r-- 1 root root 196678087 Nov 5 22:48 /input/phd-build/out/phd-runner.tar.gz
612026-11-05T22:49:09.266Z 129 1 -rw-r--r-- 1 root root 65 Nov 5 22:48 /input/phd-build/out/phd-runner.sha256.txt
622026-11-05T22:49:09.266Z 256 1 -rw-r--r-- 1 root root 65 Nov 5 22:48 /input/phd-build/out/propolis-server-debug.sha256.txt
632026-11-05T22:49:09.267Z 128 2 -rw-r--r-- 1 root root 2573 Nov 5 22:48 /input/phd-build/out/phd-run-with-args.sh
642026-11-05T22:49:09.267Z 384 263997 -rw-r--r-- 1 root root 270159143 Nov 5 22:48 /input/phd-build/out/propolis-server-debug.tar.gz
652026-11-05T22:49:09.267Z+ rm -rf /work/phd-test
662026-11-05T22:49:09.267Z+ mkdir /work/phd-test
672026-11-05T22:49:09.267Z+ for p in $indir/$indir_suffix
682026-11-05T22:49:09.267Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-11-05T22:49:24.345ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-11-05T22:49:24.345Zx phd-runner, 734682744 bytes, 1434928 tape blocks
712026-11-05T22:49:24.345Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-11-05T22:49:24.369Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-11-05T22:49:27.399Z+ for f in $(tar tf "$p")
742026-11-05T22:49:27.399Z+ chmod +x /work/phd-test/phd-runner
752026-11-05T22:49:27.424Z+ for f in $(tar tf "$p")
762026-11-05T22:49:27.424Z+ chmod +x /work/phd-test/artifacts.toml
772026-11-05T22:49:27.424Z+ for p in $indir/$indir_suffix
782026-11-05T22:49:27.424Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-11-05T22:49:40.530ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-11-05T22:49:40.530Zx propolis-server, 1051114960 bytes, 2052959 tape blocks
812026-11-05T22:49:40.567Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-11-05T22:49:44.743Z+ for f in $(tar tf "$p")
832026-11-05T22:49:44.743Z+ chmod +x /work/phd-test/propolis-server
842026-11-05T22:49:44.771Z+ for p in $indir/$indir_suffix
852026-11-05T22:49:44.771Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-11-05T22:50:02.418ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-11-05T22:50:02.418Zx target/debug/deps/propolis-addd1e09e00f8ec1, 864533424 bytes, 1688542 tape blocks
882026-11-05T22:50:02.452Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-11-05T22:50:05.777Z+ for f in $(tar tf "$p")
902026-11-05T22:50:05.777Z+ chmod +x /work/phd-test/target/debug/deps/propolis-addd1e09e00f8ec1
912026-11-05T22:50:05.807Z+ ls /work/phd-test
922026-11-05T22:50:05.807Zartifacts.toml
932026-11-05T22:50:05.807Zphd-runner
942026-11-05T22:50:05.807Zpropolis-server
952026-11-05T22:50:05.807Ztarget
962026-11-05T22:50:05.807Z+ banner Setup
972026-11-05T22:50:05.807Z #####
982026-11-05T22:50:05.807Z# # ###### ##### # # #####
992026-11-05T22:50:05.807Z# # # # # # #
1002026-11-05T22:50:05.807Z ##### ##### # # # # #
1012026-11-05T22:50:05.807Z # # # # # #####
1022026-11-05T22:50:05.807Z# # # # # # #
1032026-11-05T22:50:05.808Z ##### ###### # #### #
1042026-11-05T22:50:05.808Z
1052026-11-05T22:50:05.835Z+ tmpdir=/tmp/propolis-phd
1062026-11-05T22:50:05.835Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-11-05T22:50:05.835Z+ mkdir /tmp/propolis-phd
1082026-11-05T22:50:05.835Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-11-05T22:50:06.234Z+ banner Tests
1102026-11-05T22:50:06.272Z#######
1112026-11-05T22:50:06.272Z # ###### #### ##### ####
1122026-11-05T22:50:06.272Z # # # # #
1132026-11-05T22:50:06.272Z # ##### #### # ####
1142026-11-05T22:50:06.272Z # # # # #
1152026-11-05T22:50:06.272Z # # # # # # #
1162026-11-05T22:50:06.272Z # ###### #### # ####
1172026-11-05T22:50:06.272Z
1182026-11-05T22:50:06.272Z+ runner=/work/phd-test/phd-runner
1192026-11-05T22:50:06.273Z+ artifacts=/work/phd-test/artifacts.toml
1202026-11-05T22:50:06.273Z+ propolis=/work/phd-test/propolis-server
1212026-11-05T22:50:06.273Z+ ls /work/phd-test/phd-runner
1222026-11-05T22:50:06.273Z/work/phd-test/phd-runner
1232026-11-05T22:50:06.273Z+ ls /work/phd-test/artifacts.toml
1242026-11-05T22:50:06.273Z/work/phd-test/artifacts.toml
1252026-11-05T22:50:06.273Z+ ls /work/phd-test/propolis-server
1262026-11-05T22:50:06.273Z/work/phd-test/propolis-server
1272026-11-05T22:50:06.273Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-11-05T22:50:06.273Z+ set +e
1292026-11-05T22:50:06.273Z+ RUST_BACKTRACE=1
1302026-11-05T22:50:06.273Z+ RUST_LOG=info,phd=debug
1312026-11-05T22:50:06.273Z+ ptime -m pfexec /work/phd-test/phd-runner --emit-bunyan run --propolis-server-cmd /work/phd-test/propolis-server --crucible-downstairs-commit auto --artifact-toml-path /work/phd-test/artifacts.toml --tmp-directory /tmp/propolis-phd --artifact-directory /phd-artifacts --include-filter phd_tests::migrate::from_base --base-propolis-branch master
1322026-11-05T22:50:06.273Z+ tee /tmp/phd-runner.log
1332026-11-05T22:50:06.459Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:06.433203735Z","target":"phd_runner","line":36,"file":"phd-tests/runner/src/main.rs","runner_args":"ProcessArgs { command: Run(RunOptions { propolis_server_cmd: \"/work/phd-test/propolis-server\", base_propolis_branch: Some(\"master\"), base_propolis_commit: None, base_propolis_cmd: None, crucible_downstairs_cmd: None, crucible_downstairs_commit: Some(Auto), tmp_directory: \"/tmp/propolis-phd\", artifact_directory: Some(\"/phd-artifacts\"), output_mode: TmpFile, default_guest_cpus: 2, default_guest_memory_mib: 512, artifact_toml_path: \"/work/phd-test/artifacts.toml\", default_guest_artifact: \"alpine\", default_bootrom_artifact: \"ovmf\", include_filter: [\"phd_tests::migrate::from_base\"], exclude_filter: [], max_buildomat_wait_secs: 1200, manual_stop_on_failure: false }), disable_ansi: false, emit_bunyan: true }"}
1342026-11-05T22:50:06.491Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:06.464744345Z","target":"phd_framework::artifacts::store","line":219,"file":"phd-tests/framework/src/artifacts/store.rs","store":"Store { local_dir: \"/phd-artifacts\", artifacts: {\"alpine\": Mutex { data: StoredArtifact { description: Artifact { filename: \"alpine.iso\", kind: GuestOs(Alpine), source: RemoteServer { sha256: \"ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1\" }, untar: None }, cached_path: None } }, \"ovmf\": Mutex { data: StoredArtifact { description: Artifact { filename: \"OVMF_CODE.fd\", kind: Bootrom, source: Buildomat(BuildomatArtifact { repo: Repo(\"oxidecomputer/edk2\"), series: Series(\"image_debug\"), commit: Commit(\"bf64f45b1a58e69d126a3c6ca1e4512c88668132\"), sha256: \"740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448\" }), untar: None }, cached_path: None } }}, downloader: DownloadConfig { timeout: 600s, buildomat_backoff: ExponentialBackoff { current_interval: 1s, initial_interval: 1s, randomization_factor: 0.5, multiplier: 1.5, max_interval: 60s, start_time: Instant { tv_sec: 261, tv_nsec: 298243322 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-11-05T22:50:06.491Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:06.465323159Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-11-05T22:50:06.502Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:06.466622697Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"bd62980710dd3d6d3524aa7f6617127942b75002"}
1372026-11-05T22:50:06.502Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:06.472411325Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/bd62980710dd3d6d3524aa7f6617127942b75002/crucible-nightly.sha256.txt"}
1382026-11-05T22:50:20.982Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:20.938540666Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-11-05T22:50:22.101Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:21.847052084Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/12b00ba88d088e0c61b2d4d26f765fc83f6a76b8/propolis-server.sha256.txt"}
1402026-11-05T22:50:23.622Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:23.434309443Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-11-05T22:50:23.622Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:23.434417818Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-11-05T22:50:23.921Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:23.435111731Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-11-05T22:50:23.921Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:23.435751711Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-11-05T22:50:23.921Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:23.435789723Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-11-05T22:50:23.921Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:23.435824669Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-11-05T22:50:23.921Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:23.437225458Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
1472026-11-05T22:50:23.923Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:23.439286216Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
1482026-11-05T22:50:23.923Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:23.441686785Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
1492026-11-05T22:50:26.083Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:25.951431416Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::serial_history"}
1502026-11-05T22:50:26.309Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:25.961799193Z","target":"phd_framework::artifacts::store","line":614,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::serial_history"}
1512026-11-05T22:50:32.689Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.593799181Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::serial_history"}
1522026-11-05T22:50:32.689Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.593906063Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::serial_history"}
1532026-11-05T22:50:32.857Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.608429141Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 3.84M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
1542026-11-05T22:50:32.857Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.610718952Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-e4462b77-cdd9-4201-a48d-cc1696b93ba3\"]","path":"phd_tests::migrate::from_base::serial_history"}
1552026-11-05T22:50:32.857Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.630707113Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-e4462b77-cdd9-4201-a48d-cc1696b93ba3\", \"phd-artifacts/phd-clone-1df81f97-86e4-4d59-9801-7e6fc9b386a6\"]","path":"phd_tests::migrate::from_base::serial_history"}
1562026-11-05T22:50:32.858Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.646475444Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-1df81f97-86e4-4d59-9801-7e6fc9b386a6\"]","path":"phd_tests::migrate::from_base::serial_history"}
1572026-11-05T22:50:32.858Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.655739825Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-1df81f97-86e4-4d59-9801-7e6fc9b386a6 0B 25.3T 49.0M /phd-artifacts/phd-clone-1df81f97-86e4-4d59-9801-7e6fc9b386a6\n","path":"phd_tests::migrate::from_base::serial_history"}
1582026-11-05T22:50:32.858Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.660929891Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1592026-11-05T22:50:32.858Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.661061349Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1602026-11-05T22:50:32.858Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.661129618Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1612026-11-05T22:50:32.858Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:32.66120446Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/12b00ba88d088e0c61b2d4d26f765fc83f6a76b8/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1622026-11-05T22:50:46.960Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:46.942787366Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
1632026-11-05T22:50:46.960Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:50:46.942877928Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::serial_history"}
1642026-11-05T22:51:11.840Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:11.819729839Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::serial_history"}
1652026-11-05T22:51:11.866Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:11.821567164Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
1662026-11-05T22:51:11.935Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:11.915838905Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
1672026-11-05T22:51:11.959Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:11.929681333Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1682026-11-05T22:51:11.984Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:11.943098097Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1692026-11-05T22:51:11.985Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:11.94941843Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":39288,"path":"phd_tests::migrate::from_base::serial_history"}
1702026-11-05T22:51:12.516Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.497081033Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-11-05T22:51:12.564Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.500247371Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: b7cd01e0-0ccc-407a-82f8-e75eafac92a4, name: \"phd-vm-b7cd01e0-0ccc-407a-82f8-e75eafac92a4\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 1a95694c-3c60-4b87-94f0-ae21bb4207e7, project_id: d224c019-f2fb-45a4-b264-ca1de3b06345, sled_id: 20a909a1-9171-4743-9a05-5fa64d765a07, sled_serial: \"20a909a1-9171-4743-9a05-5fa64d765a07\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1722026-11-05T22:51:12.564Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.500432451Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1732026-11-05T22:51:12.564Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.500499438Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1742026-11-05T22:51:12.564Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.503046144Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":2,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1752026-11-05T22:51:12.564Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.50427588Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1762026-11-05T22:51:12.564Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.504367553Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","timeout_duration":"300s","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1772026-11-05T22:51:12.565Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.504425252Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
1782026-11-05T22:51:12.565Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.504478002Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1792026-11-05T22:51:12.565Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:12.504558514Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1802026-11-05T22:51:17.066Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.046362366Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":4541,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1812026-11-05T22:51:17.066Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.046472063Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
1822026-11-05T22:51:17.091Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.050510912Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1832026-11-05T22:51:17.092Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.050586655Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1842026-11-05T22:51:17.092Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.050641869Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1852026-11-05T22:51:17.117Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.074677936Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":23,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1862026-11-05T22:51:17.117Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.074845704Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
1872026-11-05T22:51:17.117Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.075315703Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1882026-11-05T22:51:17.117Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.075386557Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1892026-11-05T22:51:17.117Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.07544105Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1902026-11-05T22:51:17.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.107357111Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":31,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1912026-11-05T22:51:17.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.107482368Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1922026-11-05T22:51:17.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.107560857Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4603,"path":"phd_tests::migrate::from_base::serial_history"}
1932026-11-05T22:51:17.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.111062609Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1942026-11-05T22:51:17.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.111129355Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1952026-11-05T22:51:17.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.117608008Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":6,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1962026-11-05T22:51:17.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.117852119Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1972026-11-05T22:51:17.146Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.117956717Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1982026-11-05T22:51:17.172Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.152624351Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":34,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
1992026-11-05T22:51:17.173Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.152915061Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2002026-11-05T22:51:17.173Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.153025129Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2012026-11-05T22:51:17.198Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.163254515Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":10,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2022026-11-05T22:51:17.198Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.163499608Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2032026-11-05T22:51:17.198Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.163563098Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2042026-11-05T22:51:17.223Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.197105153Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":33,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2052026-11-05T22:51:17.249Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.21042305Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_serial_history_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::serial_history"}
2062026-11-05T22:51:17.249Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.210517198Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2072026-11-05T22:51:17.249Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.210572312Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_serial_history_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
2082026-11-05T22:51:17.249Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.213159355Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","sha256":"None","path":"phd_tests::migrate::from_base::serial_history"}
2092026-11-05T22:51:17.249Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.213236511Z","target":"phd_framework::artifacts::store","line":69,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2102026-11-05T22:51:17.249Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.213301584Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
2112026-11-05T22:51:17.249Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.213391885Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2122026-11-05T22:51:17.283Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 929","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.264002299Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
2132026-11-05T22:51:17.308Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.275008314Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":64,"path":"phd_tests::migrate::from_base::serial_history"}
2142026-11-05T22:51:17.308Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.275101129Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2152026-11-05T22:51:17.308Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.275692838Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"0eb6ca4a-c741-44da-90fa-3f7dc96f30ea","timeout_duration":"45s","source":"migration_serial_history_base","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2162026-11-05T22:51:17.308Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.275762801Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","vm":"migration_serial_history_base_lifecycle_0","target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2172026-11-05T22:51:17.308Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:17.276329332Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source":"migration_serial_history_base","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","vm":"migration_serial_history_base_lifecycle_0","target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2182026-11-05T22:51:18.167Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:18.147556876Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 87f69b8c-ae8d-4d8c-9214-8005299cabd3, name: \"phd-vm-87f69b8c-ae8d-4d8c-9214-8005299cabd3\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 1a95694c-3c60-4b87-94f0-ae21bb4207e7, project_id: d224c019-f2fb-45a4-b264-ca1de3b06345, sled_id: 9868eb61-fc12-4109-b796-1ff00bc803da, sled_serial: \"9868eb61-fc12-4109-b796-1ff00bc803da\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_serial_history_base","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","vm":"migration_serial_history_base_lifecycle_0","target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2192026-11-05T22:51:18.196Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:18.147879376Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","migration_id":"0eb6ca4a-c741-44da-90fa-3f7dc96f30ea","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2202026-11-05T22:51:20.683Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:20.663402655Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7756}}"}
2212026-11-05T22:51:22.525Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.502252364Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2222026-11-05T22:51:22.525Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.502335061Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","elapsed_milliseconds":4354,"target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","migration_id":"0eb6ca4a-c741-44da-90fa-3f7dc96f30ea","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2232026-11-05T22:51:22.551Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.505387594Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2242026-11-05T22:51:22.551Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.510597116Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_serial_history_base","vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2252026-11-05T22:51:22.551Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.513289498Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","path":"phd_tests::migrate::from_base::serial_history"}
2262026-11-05T22:51:22.551Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.513517178Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2272026-11-05T22:51:22.551Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.514198116Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10017}
2282026-11-05T22:51:22.551Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.514701158Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2292026-11-05T22:51:22.553Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.514786699Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2302026-11-05T22:51:22.553Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.515200963Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","path":"phd_tests::migrate::from_base::serial_history"}
2312026-11-05T22:51:22.606Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.58666743Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":77,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2322026-11-05T22:51:22.634Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.58879295Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":10659,"vm_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","path":"phd_tests::migrate::from_base::serial_history"}
2332026-11-05T22:51:22.891Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.871687563Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_serial_history_base_lifecycle_0","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","path":"phd_tests::migrate::from_base::serial_history"}
2342026-11-05T22:51:22.963Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.94329645Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","path":"phd_tests::migrate::from_base::serial_history"}
2352026-11-05T22:51:22.963Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.943405657Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-1df81f97-86e4-4d59-9801-7e6fc9b386a6\"]","verb":"destroy","vm":"migration_serial_history_base_lifecycle_0","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","path":"phd_tests::migrate::from_base::serial_history"}
2362026-11-05T22:51:22.989Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.969309516Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","path":"phd_tests::migrate::from_base::serial_history"}
2372026-11-05T22:51:23.015Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.969408804Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-e4462b77-cdd9-4201-a48d-cc1696b93ba3\"]","vm":"migration_serial_history_base_lifecycle_0","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","path":"phd_tests::migrate::from_base::serial_history"}
2382026-11-05T22:51:23.015Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.984885093Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":471,"vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","path":"phd_tests::migrate::from_base::serial_history"}
2392026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985218333Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":470}
2402026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985220527Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":5709,"target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4"}
2412026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985326107Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2422026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985328812Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"b7cd01e0-0ccc-407a-82f8-e75eafac92a4","elapsed_milliseconds":5710,"target_id":"87f69b8c-ae8d-4d8c-9214-8005299cabd3","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2432026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.98537011Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2442026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985386451Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":59548,"path":"phd_tests::migrate::from_base::serial_history"}
2452026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985406359Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2462026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985553718Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2472026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985664607Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2482026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985733928Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2492026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985801496Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2502026-11-05T22:51:23.016Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.985882459Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2512026-11-05T22:51:23.041Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.99557519Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.28G 25.3T 1.28G /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2522026-11-05T22:51:23.041Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:22.995666783Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-5cb03b20-e214-4a94-b032-f2b81d2787d8\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-11-05T22:51:23.043Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.010743056Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-5cb03b20-e214-4a94-b032-f2b81d2787d8\", \"phd-artifacts/phd-clone-0f7fa0dd-9d65-4e0c-9f6e-cd760492d371\"]","verb":"clone","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-11-05T22:51:23.068Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.027905924Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-0f7fa0dd-9d65-4e0c-9f6e-cd760492d371\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-11-05T22:51:23.069Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.037642428Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-0f7fa0dd-9d65-4e0c-9f6e-cd760492d371 0B 25.3T 1.28G /phd-artifacts/phd-clone-0f7fa0dd-9d65-4e0c-9f6e-cd760492d371\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-11-05T22:51:23.069Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.038372919Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2572026-11-05T22:51:23.069Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.038520208Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2582026-11-05T22:51:23.069Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.038630727Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2592026-11-05T22:51:23.069Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.038707412Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2602026-11-05T22:51:23.069Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.038786762Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2612026-11-05T22:51:23.108Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.088180656Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2622026-11-05T22:51:23.133Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.099837932Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":61,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2632026-11-05T22:51:23.133Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.099974651Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2642026-11-05T22:51:23.133Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.100749406Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2652026-11-05T22:51:23.683Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.662238209Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2662026-11-05T22:51:23.733Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.66324359Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: b4022c23-ed43-418c-9d67-43b90f698a2e, name: \"phd-vm-b4022c23-ed43-418c-9d67-43b90f698a2e\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: b5b7ed58-440a-4972-bc91-d7a6fa7972a3, project_id: b014ed4c-779b-42a0-9d0a-fc02d90d22c2, sled_id: 0bda81f6-7e94-4050-91c9-2bf23258c27f, sled_serial: \"0bda81f6-7e94-4050-91c9-2bf23258c27f\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2672026-11-05T22:51:23.733Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.663395748Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2682026-11-05T22:51:23.733Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.66345532Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2692026-11-05T22:51:23.733Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.664367946Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2702026-11-05T22:51:23.733Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.664466242Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2712026-11-05T22:51:23.733Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.664526576Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","timeout_duration":"300s","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-11-05T22:51:23.733Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.664578785Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2732026-11-05T22:51:23.733Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.664626545Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2742026-11-05T22:51:23.733Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:23.664677602Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2752026-11-05T22:51:28.305Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.284884572Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":4620,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2762026-11-05T22:51:28.305Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.284984871Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2772026-11-05T22:51:28.330Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.285184258Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2782026-11-05T22:51:28.330Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.28524317Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2792026-11-05T22:51:28.330Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.285297453Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2802026-11-05T22:51:28.330Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.303331829Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2812026-11-05T22:51:28.330Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.303451025Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2822026-11-05T22:51:28.330Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.303732908Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2832026-11-05T22:51:28.330Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.303783884Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2842026-11-05T22:51:28.330Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.303827477Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2852026-11-05T22:51:28.366Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.336945269Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2862026-11-05T22:51:28.366Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.337113126Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2872026-11-05T22:51:28.490Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.337195322Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4672,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2882026-11-05T22:51:28.490Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.337480751Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2892026-11-05T22:51:28.490Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.33759118Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2902026-11-05T22:51:28.491Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.348159527Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2912026-11-05T22:51:28.491Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.348439246Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2922026-11-05T22:51:28.491Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.348549545Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2932026-11-05T22:51:28.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.3816691Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2942026-11-05T22:51:28.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.382664513Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2952026-11-05T22:51:28.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.382775373Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2962026-11-05T22:51:28.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.392526564Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":9,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2972026-11-05T22:51:28.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.392850487Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2982026-11-05T22:51:28.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.392923876Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2992026-11-05T22:51:28.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.425067806Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3002026-11-05T22:51:28.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.425404433Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3012026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.42554583Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3022026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.436531667Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3032026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.436783974Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3042026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.436910443Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3052026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.469219276Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3062026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.469510246Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3072026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.469619683Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3082026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.480567508Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3092026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.480880289Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3102026-11-05T22:51:28.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.480994996Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3112026-11-05T22:51:28.553Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.513145209Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3122026-11-05T22:51:28.553Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.513474181Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3132026-11-05T22:51:28.553Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.513613083Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3142026-11-05T22:51:28.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.524049661Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3152026-11-05T22:51:28.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.524300956Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3162026-11-05T22:51:28.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.524426053Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3172026-11-05T22:51:28.580Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.55778405Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3182026-11-05T22:51:28.580Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.558658894Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3192026-11-05T22:51:28.580Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.55873058Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3202026-11-05T22:51:28.605Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.568032123Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":9,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3212026-11-05T22:51:28.605Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.568294709Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3222026-11-05T22:51:28.605Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.568374711Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3232026-11-05T22:51:28.634Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.601338712Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3242026-11-05T22:51:28.634Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.601549862Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3252026-11-05T22:51:28.634Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.601707931Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3262026-11-05T22:51:28.634Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.601803241Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3272026-11-05T22:51:28.635Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.601930141Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3282026-11-05T22:51:28.635Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.602037845Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3292026-11-05T22:51:28.636Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.602205161Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3302026-11-05T22:51:28.671Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 939","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.649421907Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3312026-11-05T22:51:28.696Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.660245788Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":58,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3322026-11-05T22:51:28.696Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.660329997Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
3332026-11-05T22:51:28.697Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.66039507Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"451ef22e-5945-4d9a-8236-0306f0a58c5a","timeout_duration":"45s","source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
3342026-11-05T22:51:28.697Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.66045856Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
3352026-11-05T22:51:28.697Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:28.66102421Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
3362026-11-05T22:51:29.377Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:29.357227265Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 1a7464c2-078d-4230-befe-09bd5a01b7df, name: \"phd-vm-1a7464c2-078d-4230-befe-09bd5a01b7df\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: b5b7ed58-440a-4972-bc91-d7a6fa7972a3, project_id: b014ed4c-779b-42a0-9d0a-fc02d90d22c2, sled_id: 4d9f6254-b0d7-40a7-9bdb-d3f452165eb8, sled_serial: \"4d9f6254-b0d7-40a7-9bdb-d3f452165eb8\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
3372026-11-05T22:51:29.377Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:29.357415801Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","migration_id":"451ef22e-5945-4d9a-8236-0306f0a58c5a","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
3382026-11-05T22:51:31.877Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:31.855158806Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
3392026-11-05T22:51:32.161Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.140899091Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
3402026-11-05T22:51:32.162Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.14099408Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","migration_id":"451ef22e-5945-4d9a-8236-0306f0a58c5a","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":2783,"path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
3412026-11-05T22:51:32.190Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.14391804Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3422026-11-05T22:51:32.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.144203049Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3432026-11-05T22:51:32.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.144269825Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo 3 > /proc/sys/vm/drop_caches","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3442026-11-05T22:51:32.191Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.145665545Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3452026-11-05T22:51:32.239Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.218745905Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":74,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3462026-11-05T22:51:32.264Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.218990137Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","elapsed_milliseconds":9118,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3472026-11-05T22:51:32.264Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.219222406Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":74,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3482026-11-05T22:51:32.264Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.219490643Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3492026-11-05T22:51:32.264Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.219565104Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3502026-11-05T22:51:32.289Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.255440051Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":35,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3512026-11-05T22:51:32.289Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.255710462Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3522026-11-05T22:51:32.289Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.255795423Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3532026-11-05T22:51:32.289Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.26723617Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3542026-11-05T22:51:32.289Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.267508385Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3552026-11-05T22:51:32.290Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.267643139Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3562026-11-05T22:51:32.320Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.300146871Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3572026-11-05T22:51:32.345Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.300422512Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3582026-11-05T22:51:32.345Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.300536497Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3592026-11-05T22:51:32.345Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.310812501Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3602026-11-05T22:51:32.345Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.310983505Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3612026-11-05T22:51:32.345Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.311056443Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3622026-11-05T22:51:32.371Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.344883757Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3632026-11-05T22:51:32.371Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.345172343Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3642026-11-05T22:51:32.371Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.345267322Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"mount | grep ' / type tmpfs '","timeout_duration":"Explicit(15s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3652026-11-05T22:51:32.395Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.355726503Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3662026-11-05T22:51:32.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.355977738Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3672026-11-05T22:51:32.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.356087085Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3682026-11-05T22:51:32.421Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.389758584Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3692026-11-05T22:51:32.422Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.39001449Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3702026-11-05T22:51:32.422Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.390119499Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls /media/nvme0n1/boot","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3712026-11-05T22:51:32.453Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.40164165Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3722026-11-05T22:51:32.453Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.401888176Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3732026-11-05T22:51:32.454Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.401996992Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3742026-11-05T22:51:32.480Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.44585204Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":43,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3752026-11-05T22:51:32.480Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.446007094Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3762026-11-05T22:51:32.480Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.446075503Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3772026-11-05T22:51:32.480Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.456409677Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3782026-11-05T22:51:32.480Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.456659349Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3792026-11-05T22:51:32.480Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.456764518Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3802026-11-05T22:51:32.508Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.479373917Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3812026-11-05T22:51:32.508Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.479620914Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3822026-11-05T22:51:32.508Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.479722927Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"! dmesg | grep -q 'reset controller'","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3832026-11-05T22:51:32.533Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.490072981Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3842026-11-05T22:51:32.534Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.490304569Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3852026-11-05T22:51:32.534Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.490408606Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3862026-11-05T22:51:32.558Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.523249184Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3872026-11-05T22:51:32.558Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.523403847Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3882026-11-05T22:51:32.558Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.523467697Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3892026-11-05T22:51:32.558Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.534060611Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3902026-11-05T22:51:32.561Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.534373342Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3912026-11-05T22:51:32.561Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.53448833Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3922026-11-05T22:51:32.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.566674711Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3932026-11-05T22:51:32.613Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.566833681Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3942026-11-05T22:51:32.613Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.567025404Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3952026-11-05T22:51:32.613Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.567167723Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8904}
3962026-11-05T22:51:32.613Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.56718201Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3972026-11-05T22:51:32.613Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.567290465Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3982026-11-05T22:51:32.613Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.568451972Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3992026-11-05T22:51:32.879Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.843419864Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4002026-11-05T22:51:32.941Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.920240187Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4012026-11-05T22:51:32.941Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.920357579Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-0f7fa0dd-9d65-4e0c-9f6e-cd760492d371\"]","verb":"destroy","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4022026-11-05T22:51:32.966Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.944485921Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4032026-11-05T22:51:32.966Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.944552266Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-5cb03b20-e214-4a94-b032-f2b81d2787d8\"]","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4042026-11-05T22:51:32.991Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.9593968Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":392,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4052026-11-05T22:51:32.991Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.959646663Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","source":"migration_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","elapsed_milliseconds":4299,"source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e"}
4062026-11-05T22:51:32.991Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.959733667Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":392}
4072026-11-05T22:51:32.991Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.959747373Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b4022c23-ed43-418c-9d67-43b90f698a2e","target_id":"1a7464c2-078d-4230-befe-09bd5a01b7df","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":4299,"path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
4082026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.959821824Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":9974,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4092026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.959844617Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
4102026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.959892207Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
4112026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.959942151Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4122026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.960152599Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4132026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.960305939Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4142026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.960399466Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4152026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.960461524Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4162026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.960537698Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4172026-11-05T22:51:32.993Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.970626798Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.28G 25.3T 1.28G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-11-05T22:51:32.994Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.970811417Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-30683d43-6458-40cc-be6c-96768e83a1c8\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4192026-11-05T22:51:33.019Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:32.989167152Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-30683d43-6458-40cc-be6c-96768e83a1c8\", \"phd-artifacts/phd-clone-d33b98a7-2738-471f-9c3a-c44a632e2073\"]","verb":"clone","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4202026-11-05T22:51:33.046Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.006550307Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-d33b98a7-2738-471f-9c3a-c44a632e2073\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4212026-11-05T22:51:33.046Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.015108723Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-d33b98a7-2738-471f-9c3a-c44a632e2073 0B 25.3T 1.28G /phd-artifacts/phd-clone-d33b98a7-2738-471f-9c3a-c44a632e2073\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4222026-11-05T22:51:33.046Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.015842781Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4232026-11-05T22:51:33.046Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.015915809Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4242026-11-05T22:51:33.047Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.015989378Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4252026-11-05T22:51:33.047Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.016057006Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4262026-11-05T22:51:33.047Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.016136076Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4272026-11-05T22:51:33.084Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 948","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.063685433Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4282026-11-05T22:51:33.110Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.075593604Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":59}
4292026-11-05T22:51:33.110Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.075697701Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4302026-11-05T22:51:33.110Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.076371555Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4312026-11-05T22:51:33.889Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.86941775Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
4322026-11-05T22:51:33.938Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.87058617Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: f2e0a329-43d4-4544-983e-380e45bca13c, name: \"phd-vm-f2e0a329-43d4-4544-983e-380e45bca13c\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f45731a9-130d-486a-a9b9-dd66868ba7ec, project_id: c674ff45-5773-4124-9fc8-fefe6ab56ccd, sled_id: 5ff478bc-8fb7-4d15-ba61-2aaa8cac4400, sled_serial: \"5ff478bc-8fb7-4d15-ba61-2aaa8cac4400\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4332026-11-05T22:51:33.938Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.870755249Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4342026-11-05T22:51:33.938Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.870818108Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4352026-11-05T22:51:33.938Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.872266167Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":1}
4362026-11-05T22:51:33.938Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.872354985Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4372026-11-05T22:51:33.938Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.872417253Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","timeout_duration":"300s","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4382026-11-05T22:51:33.938Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.872470143Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4392026-11-05T22:51:33.938Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.872518033Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4402026-11-05T22:51:33.938Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:33.872569811Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4412026-11-05T22:51:38.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.489834584Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":4617}
4422026-11-05T22:51:38.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.489934263Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4432026-11-05T22:51:38.512Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.490130825Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4442026-11-05T22:51:38.512Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.490192561Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4452026-11-05T22:51:38.512Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.490250571Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4462026-11-05T22:51:38.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.508573984Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":18}
4472026-11-05T22:51:38.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.508631623Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4482026-11-05T22:51:38.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.508842893Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4492026-11-05T22:51:38.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.508894761Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4502026-11-05T22:51:38.539Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.508946329Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4512026-11-05T22:51:38.564Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.542061626Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":33}
4522026-11-05T22:51:38.564Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.542246726Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-11-05T22:51:38.564Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.542327359Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4669}
4542026-11-05T22:51:38.565Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.542582501Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4552026-11-05T22:51:38.565Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.542690015Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4562026-11-05T22:51:38.591Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.553450425Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":10}
4572026-11-05T22:51:38.592Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.553739321Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4582026-11-05T22:51:38.592Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.553850622Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4592026-11-05T22:51:38.618Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.587054557Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":33}
4602026-11-05T22:51:38.618Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.587310431Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4612026-11-05T22:51:38.618Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.587420048Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4622026-11-05T22:51:38.644Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.597939292Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":10}
4632026-11-05T22:51:38.644Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.598193814Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4642026-11-05T22:51:38.644Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.598263546Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4652026-11-05T22:51:38.669Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.631263125Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":32}
4662026-11-05T22:51:38.669Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.631520732Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4672026-11-05T22:51:38.670Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.631631291Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4682026-11-05T22:51:38.670Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.642845138Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":11}
4692026-11-05T22:51:38.670Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.643148152Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4702026-11-05T22:51:38.670Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.643272587Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4712026-11-05T22:51:38.696Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.675540091Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":32}
4722026-11-05T22:51:38.722Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.675869655Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4732026-11-05T22:51:38.722Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.675992737Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4742026-11-05T22:51:38.722Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.686457418Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":10}
4752026-11-05T22:51:38.722Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.68669643Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4762026-11-05T22:51:38.722Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.686802741Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4772026-11-05T22:51:38.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.7200348Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":33}
4782026-11-05T22:51:38.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.720291465Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4792026-11-05T22:51:38.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.72039996Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4802026-11-05T22:51:38.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.730812873Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":10}
4812026-11-05T22:51:38.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.730943651Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4822026-11-05T22:51:38.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.730998805Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4832026-11-05T22:51:38.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.764115676Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":33}
4842026-11-05T22:51:38.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.764441843Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4852026-11-05T22:51:38.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.764559886Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4862026-11-05T22:51:38.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.774989502Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":10}
4872026-11-05T22:51:38.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.775242911Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4882026-11-05T22:51:38.811Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.775361656Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
4892026-11-05T22:51:38.839Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.808652446Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":33}
4902026-11-05T22:51:38.839Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.80885543Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4912026-11-05T22:51:38.839Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.808996186Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4922026-11-05T22:51:38.839Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.809087258Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4932026-11-05T22:51:38.839Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.80920967Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4942026-11-05T22:51:38.839Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.809312314Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4952026-11-05T22:51:38.841Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.809445405Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4962026-11-05T22:51:38.877Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 949","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.855893979Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4972026-11-05T22:51:38.907Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.867020692Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":57}
4982026-11-05T22:51:38.907Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.867106134Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","target":"migration_from_base_and_back_lifecycle_0","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back"}
4992026-11-05T22:51:38.907Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.867179272Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"fcaf0e41-d6be-406e-accf-9d3e5702e240","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","target":"migration_from_base_and_back_lifecycle_0","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back"}
5002026-11-05T22:51:38.907Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.867248673Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","target":"migration_from_base_and_back_lifecycle_0","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
5012026-11-05T22:51:38.907Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:38.867874827Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","target":"migration_from_base_and_back_lifecycle_0","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
5022026-11-05T22:51:39.504Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:39.482455007Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: fd2a4c76-3c6a-4318-a4af-d1a45a06850e, name: \"phd-vm-fd2a4c76-3c6a-4318-a4af-d1a45a06850e\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f45731a9-130d-486a-a9b9-dd66868ba7ec, project_id: c674ff45-5773-4124-9fc8-fefe6ab56ccd, sled_id: ab2758eb-068f-4697-91a1-232e9d32b197, sled_serial: \"ab2758eb-068f-4697-91a1-232e9d32b197\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","target":"migration_from_base_and_back_lifecycle_0","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
5032026-11-05T22:51:39.504Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:39.482690522Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","migration_id":"fcaf0e41-d6be-406e-accf-9d3e5702e240","target":"migration_from_base_and_back_lifecycle_0","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back"}
5042026-11-05T22:51:42.005Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:41.984605888Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
5052026-11-05T22:51:42.152Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.131172585Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","target":"migration_from_base_and_back_lifecycle_0","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back"}
5062026-11-05T22:51:42.152Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.13123363Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","migration_id":"fcaf0e41-d6be-406e-accf-9d3e5702e240","target":"migration_from_base_and_back_lifecycle_0","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back","elapsed_milliseconds":2648}
5072026-11-05T22:51:42.177Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.133388506Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
5082026-11-05T22:51:42.177Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.133612479Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e"}
5092026-11-05T22:51:42.180Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.133679566Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e"}
5102026-11-05T22:51:42.180Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.135014341Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c"}
5112026-11-05T22:51:42.230Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.209340877Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":75}
5122026-11-05T22:51:42.255Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.209522571Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f2e0a329-43d4-4544-983e-380e45bca13c","elapsed_milliseconds":9133}
5132026-11-05T22:51:42.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.209887461Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","elapsed_milliseconds":76}
5142026-11-05T22:51:42.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.210150699Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e"}
5152026-11-05T22:51:42.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.210228877Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e"}
5162026-11-05T22:51:42.282Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.243204861Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","elapsed_milliseconds":32}
5172026-11-05T22:51:42.282Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.243356968Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__BASE_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5182026-11-05T22:51:42.282Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.243514787Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5192026-11-05T22:51:42.282Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.243607031Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5202026-11-05T22:51:42.282Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.243726507Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5212026-11-05T22:51:42.282Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.243829552Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9004","server_path":"\"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5222026-11-05T22:51:42.282Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.243962684Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5232026-11-05T22:51:42.316Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 951","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.295540129Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5242026-11-05T22:51:42.341Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.306249523Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":62}
5252026-11-05T22:51:42.341Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.30635914Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","target":"migration_from_base_and_back_lifecycle_1","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0"}
5262026-11-05T22:51:42.341Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.306437218Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d4cb711a-5935-42d7-86bf-0ba5443d6676","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","target":"migration_from_base_and_back_lifecycle_1","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0"}
5272026-11-05T22:51:42.342Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.306505347Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","target":"migration_from_base_and_back_lifecycle_1","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1"}
5282026-11-05T22:51:42.342Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.307105291Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","target":"migration_from_base_and_back_lifecycle_1","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1"}
5292026-11-05T22:51:42.727Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.705555614Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c5c00851-b35f-4563-8751-e499ebf3bf07, name: \"phd-vm-c5c00851-b35f-4563-8751-e499ebf3bf07\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f45731a9-130d-486a-a9b9-dd66868ba7ec, project_id: c674ff45-5773-4124-9fc8-fefe6ab56ccd, sled_id: f3fb1d3e-6f12-4980-8227-e3d5c7b82411, sled_serial: \"f3fb1d3e-6f12-4980-8227-e3d5c7b82411\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","target":"migration_from_base_and_back_lifecycle_1","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1"}
5302026-11-05T22:51:42.756Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:42.705776602Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","migration_id":"d4cb711a-5935-42d7-86bf-0ba5443d6676","target":"migration_from_base_and_back_lifecycle_1","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0"}
5312026-11-05T22:51:45.224Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:45.202293727Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7894}}"}
5322026-11-05T22:51:47.060Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.039173309Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","target":"migration_from_base_and_back_lifecycle_1","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0"}
5332026-11-05T22:51:47.060Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.039273919Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","migration_id":"d4cb711a-5935-42d7-86bf-0ba5443d6676","target":"migration_from_base_and_back_lifecycle_1","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":4333}
5342026-11-05T22:51:47.085Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.042415841Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e"}
5352026-11-05T22:51:47.085Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.042723984Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07"}
5362026-11-05T22:51:47.085Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.042810397Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07"}
5372026-11-05T22:51:47.085Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.043913714Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e"}
5382026-11-05T22:51:47.143Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.122132583Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","elapsed_milliseconds":79}
5392026-11-05T22:51:47.169Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.122329716Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back","elapsed_milliseconds":8255,"target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","vm_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0"}
5402026-11-05T22:51:47.169Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.12238972Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","target":"migration_from_base_and_back_lifecycle_0","source_id":"f2e0a329-43d4-4544-983e-380e45bca13c","source":"migration_from_base_and_back","elapsed_milliseconds":8255}
5412026-11-05T22:51:47.169Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.122401863Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","elapsed_milliseconds":79}
5422026-11-05T22:51:47.169Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.122639582Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07"}
5432026-11-05T22:51:47.169Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.12271782Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07"}
5442026-11-05T22:51:47.196Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.154838667Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","elapsed_milliseconds":32}
5452026-11-05T22:51:47.197Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.155025671Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5462026-11-05T22:51:47.197Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.155201243Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5472026-11-05T22:51:47.197Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.155316922Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5482026-11-05T22:51:47.197Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.155450945Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5492026-11-05T22:51:47.197Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.155551125Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9006","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5502026-11-05T22:51:47.197Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.155679738Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5512026-11-05T22:51:47.229Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 953","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.207725697Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5522026-11-05T22:51:47.256Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.222275634Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":66}
5532026-11-05T22:51:47.256Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.222428303Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","target":"migration_from_base_and_back_lifecycle_2","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1"}
5542026-11-05T22:51:47.256Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.222543701Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"60a044d7-511c-4e9e-9e8d-2a16c939591b","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","target":"migration_from_base_and_back_lifecycle_2","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1"}
5552026-11-05T22:51:47.256Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.22264887Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","target":"migration_from_base_and_back_lifecycle_2","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2"}
5562026-11-05T22:51:47.256Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:47.223401634Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","target":"migration_from_base_and_back_lifecycle_2","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2"}
5572026-11-05T22:51:48.072Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:48.0494481Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: daf3244e-88e0-4d74-b850-be885a5e56a8, name: \"phd-vm-daf3244e-88e0-4d74-b850-be885a5e56a8\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f45731a9-130d-486a-a9b9-dd66868ba7ec, project_id: c674ff45-5773-4124-9fc8-fefe6ab56ccd, sled_id: 5f9828df-bff2-4508-b736-b37e253e0469, sled_serial: \"5f9828df-bff2-4508-b736-b37e253e0469\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","target":"migration_from_base_and_back_lifecycle_2","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2"}
5582026-11-05T22:51:48.072Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:48.049626969Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","migration_id":"60a044d7-511c-4e9e-9e8d-2a16c939591b","target":"migration_from_base_and_back_lifecycle_2","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1"}
5592026-11-05T22:51:50.549Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:50.527375868Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7941}}"}
5602026-11-05T22:51:52.533Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.511337646Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","target":"migration_from_base_and_back_lifecycle_2","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1"}
5612026-11-05T22:51:52.533Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.511422196Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","migration_id":"60a044d7-511c-4e9e-9e8d-2a16c939591b","target":"migration_from_base_and_back_lifecycle_2","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":4461}
5622026-11-05T22:51:52.558Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.513912786Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07"}
5632026-11-05T22:51:52.558Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.514141749Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5642026-11-05T22:51:52.558Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.514214837Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5652026-11-05T22:51:52.558Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.516237382Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07"}
5662026-11-05T22:51:52.638Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.593728223Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","elapsed_milliseconds":79}
5672026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.594036396Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","elapsed_milliseconds":79}
5682026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.594024674Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":10287,"target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","vm_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1"}
5692026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.594175158Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","target":"migration_from_base_and_back_lifecycle_1","source_id":"fd2a4c76-3c6a-4318-a4af-d1a45a06850e","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":10287}
5702026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.594292711Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5712026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.59440353Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5722026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.62635098Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","elapsed_milliseconds":31}
5732026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.626548854Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5742026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.626805098Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5752026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.626951074Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":18757}
5762026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.626938861Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5772026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.627040383Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5782026-11-05T22:51:52.663Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:52.628560288Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5792026-11-05T22:51:53.146Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.124708517Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5802026-11-05T22:51:53.215Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.19253367Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5812026-11-05T22:51:53.215Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.192649509Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-d33b98a7-2738-471f-9c3a-c44a632e2073\"]","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5822026-11-05T22:51:53.241Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.217313764Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5832026-11-05T22:51:53.241Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.217418031Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-30683d43-6458-40cc-be6c-96768e83a1c8\"]","verb":"destroy","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8"}
5842026-11-05T22:51:53.266Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.233665388Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","elapsed_milliseconds":606}
5852026-11-05T22:51:53.266Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.233941751Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":6011,"target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","vm_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2"}
5862026-11-05T22:51:53.266Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.233973692Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":606}
5872026-11-05T22:51:53.266Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.234028485Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"daf3244e-88e0-4d74-b850-be885a5e56a8","target":"migration_from_base_and_back_lifecycle_2","source_id":"c5c00851-b35f-4563-8751-e499ebf3bf07","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":6011}
5882026-11-05T22:51:53.267Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.234087467Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5892026-11-05T22:51:53.267Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.234092817Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":20273}
5902026-11-05T22:51:53.267Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.234134275Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5912026-11-05T22:51:53.267Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 89.80s
5922026-11-05T22:51:53.267Z
5932026-11-05T22:51:53.267Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220060","pid":923,"time":"2026-11-05T22:51:53.234794614Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5942026-11-05T22:51:53.409Z
5952026-11-05T22:51:53.409Zreal 1:46.996359175
5962026-11-05T22:51:53.409Zuser 50.877830370
5972026-11-05T22:51:53.409Zsys 19.734478867
5982026-11-05T22:51:53.409Ztrap 0.007587676
5992026-11-05T22:51:53.435Ztflt 0.003496800
6002026-11-05T22:51:53.435Zdflt 0.001781340
6012026-11-05T22:51:53.436Zkflt 0.000000000
6022026-11-05T22:51:53.436Zlock 4:07:06.354383665
6032026-11-05T22:51:53.436Zslp 4:33.440766743
6042026-11-05T22:51:53.436Zlat 1.762080357
6052026-11-05T22:51:53.436Zstop 42.761220605
6062026-11-05T22:51:53.436Z+ failcount=0
6072026-11-05T22:51:53.436Z+ set -e
6082026-11-05T22:51:53.436Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
6092026-11-05T22:51:53.437ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
6102026-11-05T22:51:53.437Za ./ 0K
6112026-11-05T22:51:53.437Za ./phd_tests::migrate::from_base::serial_history/ 0K
6122026-11-05T22:51:53.437Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 159K
6132026-11-05T22:51:53.437Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
6142026-11-05T22:51:53.437Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
6152026-11-05T22:51:53.437Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 165K
6162026-11-05T22:51:53.437Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
6172026-11-05T22:51:53.437Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
6182026-11-05T22:51:53.437Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 158K
6192026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
6202026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
6212026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 164K
6222026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
6232026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
6242026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 158K
6252026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
6262026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
6272026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 269K
6282026-11-05T22:51:53.438Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
6292026-11-05T22:51:53.439Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 269K
6302026-11-05T22:51:53.439Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
6312026-11-05T22:51:53.439Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 165K
6322026-11-05T22:51:53.439Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
6332026-11-05T22:51:53.465Z+ exitcode=0
6342026-11-05T22:51:53.466Z+ '[' 0 -eq 0 ']'
6352026-11-05T22:51:53.466Z+ echo
6362026-11-05T22:51:53.466Z+ echo 'ALL TESTS PASSED'
6372026-11-05T22:51:53.466Z
6382026-11-05T22:51:53.466ZALL TESTS PASSED
6392026-11-05T22:51:53.466Z+ echo
6402026-11-05T22:51:53.466Z
6412026-11-05T22:51:53.466Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6422026-11-05T22:51:53.466Z+ read
6432026-11-05T22:51:53.466Z+ exit 0
6442026-11-05T22:51:53.466Zprocess exited: duration 166858 ms, exit code 0
 
6452026-11-05T22:51:53.556Zfound 2 output files
6462026-11-05T22:51:53.556Zuploading: /tmp/phd-runner.log (202737 bytes)
6472026-11-05T22:51:54.761Zuploaded: /tmp/phd-runner.log
6482026-11-05T22:51:54.761Zuploading: /tmp/phd-tmp-files.tar.gz (134260 bytes)
6492026-11-05T22:51:55.956Zuploaded: /tmp/phd-tmp-files.tar.gz