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

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

Buildomat Job: 01KR2A12YZ9PWQ76BATH4Z6WH2

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-05-07T23:00:22.842Zjob dependencies complete; ready to run (waiting for 12 m 11 s)
22026-05-07T23:52:32.269Zjob assigned to worker 01KR2DGZX5G2WSSCD5HNQ6VK7Y [factory edgar, gimlet/BRM42220010/934] (queued for 52 m 9 s)
32026-05-07T23:52:33.239Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-05-07T23:52:33.285Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-05-07T23:52:33.285Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-05-07T23:52:33.332Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-05-07T23:52:33.332Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-05-07T23:52:38.867Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-05-07T23:52:38.891Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-05-07T23:52:38.916Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-05-07T23:52:38.916Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-05-07T23:52:48.258Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-05-07T23:52:48.258Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-05-07T23:52:55.827Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-05-07T23:52:55.827Zstarting task 0: "setup"
162026-05-07T23:52:55.853Z++ uname -s
172026-05-07T23:52:55.853Z+ kern=SunOS
182026-05-07T23:52:55.853Z+ build_user=build
192026-05-07T23:52:55.853Z+ build_uid=12345
202026-05-07T23:52:55.853Z+ work_dir=/work
212026-05-07T23:52:55.853Z+ input_dir=/input
222026-05-07T23:52:55.853Z+ [[ 0 == 12345 ]]
232026-05-07T23:52:55.853Z+ case "$kern" in
242026-05-07T23:52:55.853Z+ groupadd -g 12345 build
252026-05-07T23:52:55.877Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-05-07T23:52:57.863Z+ zfs create -o mountpoint=/work rpool/work
272026-05-07T23:52:57.891Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-05-07T23:52:57.915Z+ home_fs=
292026-05-07T23:52:57.915Z+ [[ '' == autofs ]]
302026-05-07T23:52:57.916Z+ mkdir -p /home/build
312026-05-07T23:52:57.916Z+ chown build:build /home/build /work
322026-05-07T23:52:59.904Z+ chmod 0700 /home/build /work
332026-05-07T23:52:59.928Zprocess exited: duration 4082 ms, exit code 0
 
342026-05-07T23:52:59.976Zstarting task 1: "authentication"
352026-05-07T23:53:00.045Zprocess exited: duration 67 ms, exit code 0
 
362026-05-07T23:53:00.093Zstarting task 2: "build"
372026-05-07T23:53:00.119Z+ indir=/input
382026-05-07T23:53:00.119Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-05-07T23:53:00.119Z+ phddir=/work/phd-test
402026-05-07T23:53:00.119Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-05-07T23:53:00.143Z++ pilot local disk list -H -o type,disk
422026-05-07T23:53:00.143Z++ grep -v M.2
432026-05-07T23:53:00.143Z++ cut -f 2
442026-05-07T23:53:00.192Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
452026-05-07T23:53:00.468Z+ artifactdir=/phd-artifacts
462026-05-07T23:53:00.468Z+ banner Inputs
472026-05-07T23:53:00.492Z ###
482026-05-07T23:53:00.492Z # # # ##### # # ##### ####
492026-05-07T23:53:00.492Z # ## # # # # # # #
502026-05-07T23:53:00.492Z # # # # # # # # # ####
512026-05-07T23:53:00.492Z # # # # ##### # # # #
522026-05-07T23:53:00.492Z # # ## # # # # # #
532026-05-07T23:53:00.492Z ### # # # #### # ####
542026-05-07T23:53:00.492Z
552026-05-07T23:53:00.492Z+ find /input -ls
562026-05-07T23:53:00.492Z 34 1 drwxr-xr-x 3 root root 3 May 7 23:52 /input
572026-05-07T23:53:00.492Z 2 1 drwxr-xr-x 3 root root 3 May 7 23:52 /input/phd-build
582026-05-07T23:53:00.492Z 3 2 drwxr-xr-x 2 root root 8 May 7 23:52 /input/phd-build/out
592026-05-07T23:53:00.492Z 130 119142 -rw-r--r-- 1 root root 121925580 May 7 23:52 /input/phd-build/out/phd-runner.tar.gz
602026-05-07T23:53:00.492Z 129 1 -rw-r--r-- 1 root root 65 May 7 23:52 /input/phd-build/out/phd-runner.sha256.txt
612026-05-07T23:53:00.493Z 384 207500 -rw-r--r-- 1 root root 212530703 May 7 23:52 /input/phd-build/out/propolis-server-debug.tar.gz
622026-05-07T23:53:00.493Z 512 168842 -rw-r--r-- 1 root root 172903958 May 7 23:52 /input/phd-build/out/propolis-tests-debug.tar.gz
632026-05-07T23:53:00.493Z 256 1 -rw-r--r-- 1 root root 65 May 7 23:52 /input/phd-build/out/propolis-server-debug.sha256.txt
642026-05-07T23:53:00.493Z 128 2 -rw-r--r-- 1 root root 2573 May 7 23:52 /input/phd-build/out/phd-run-with-args.sh
652026-05-07T23:53:00.493Z+ rm -rf /work/phd-test
662026-05-07T23:53:00.493Z+ mkdir /work/phd-test
672026-05-07T23:53:00.493Z+ for p in $indir/$indir_suffix
682026-05-07T23:53:00.493Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-05-07T23:53:03.645ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-05-07T23:53:03.645Zx phd-runner, 432316896 bytes, 844369 tape blocks
712026-05-07T23:53:03.645Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-05-07T23:53:03.669Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-05-07T23:53:06.667Z+ for f in $(tar tf "$p")
742026-05-07T23:53:06.667Z+ chmod +x /work/phd-test/phd-runner
752026-05-07T23:53:06.691Z+ for f in $(tar tf "$p")
762026-05-07T23:53:06.691Z+ chmod +x /work/phd-test/artifacts.toml
772026-05-07T23:53:06.691Z+ for p in $indir/$indir_suffix
782026-05-07T23:53:06.691Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-05-07T23:53:16.843ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-05-07T23:53:16.843Zx propolis-server, 809088848 bytes, 1580252 tape blocks
812026-05-07T23:53:16.867Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-05-07T23:53:22.322Z+ for f in $(tar tf "$p")
832026-05-07T23:53:22.322Z+ chmod +x /work/phd-test/propolis-server
842026-05-07T23:53:22.346Z+ for p in $indir/$indir_suffix
852026-05-07T23:53:22.346Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-05-07T23:53:36.508ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-05-07T23:53:36.508Zx target/debug/deps/propolis-a70121243652f668, 657950592 bytes, 1285060 tape blocks
882026-05-07T23:53:36.532Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-05-07T23:53:40.694Z+ for f in $(tar tf "$p")
902026-05-07T23:53:40.694Z+ chmod +x /work/phd-test/target/debug/deps/propolis-a70121243652f668
912026-05-07T23:53:40.719Z+ ls /work/phd-test
922026-05-07T23:53:40.719Zartifacts.toml
932026-05-07T23:53:40.719Zphd-runner
942026-05-07T23:53:40.719Zpropolis-server
952026-05-07T23:53:40.719Ztarget
962026-05-07T23:53:40.719Z+ banner Setup
972026-05-07T23:53:40.719Z #####
982026-05-07T23:53:40.719Z# # ###### ##### # # #####
992026-05-07T23:53:40.719Z# # # # # # #
1002026-05-07T23:53:40.719Z ##### ##### # # # # #
1012026-05-07T23:53:40.719Z # # # # # #####
1022026-05-07T23:53:40.719Z# # # # # # #
1032026-05-07T23:53:40.719Z ##### ###### # #### #
1042026-05-07T23:53:40.719Z
1052026-05-07T23:53:40.719Z+ tmpdir=/tmp/propolis-phd
1062026-05-07T23:53:40.719Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-05-07T23:53:40.719Z+ mkdir /tmp/propolis-phd
1082026-05-07T23:53:40.719Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-05-07T23:53:41.181Z+ banner Tests
1102026-05-07T23:53:41.206Z#######
1112026-05-07T23:53:41.206Z # ###### #### ##### ####
1122026-05-07T23:53:41.206Z # # # # #
1132026-05-07T23:53:41.206Z # ##### #### # ####
1142026-05-07T23:53:41.206Z # # # # #
1152026-05-07T23:53:41.206Z # # # # # # #
1162026-05-07T23:53:41.206Z # ###### #### # ####
1172026-05-07T23:53:41.207Z
1182026-05-07T23:53:41.207Z+ runner=/work/phd-test/phd-runner
1192026-05-07T23:53:41.207Z+ artifacts=/work/phd-test/artifacts.toml
1202026-05-07T23:53:41.207Z+ propolis=/work/phd-test/propolis-server
1212026-05-07T23:53:41.207Z+ ls /work/phd-test/phd-runner
1222026-05-07T23:53:41.207Z/work/phd-test/phd-runner
1232026-05-07T23:53:41.207Z+ ls /work/phd-test/artifacts.toml
1242026-05-07T23:53:41.207Z/work/phd-test/artifacts.toml
1252026-05-07T23:53:41.207Z+ ls /work/phd-test/propolis-server
1262026-05-07T23:53:41.207Z/work/phd-test/propolis-server
1272026-05-07T23:53:41.207Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-05-07T23:53:41.207Z+ set +e
1292026-05-07T23:53:41.207Z+ RUST_BACKTRACE=1
1302026-05-07T23:53:41.207Z+ RUST_LOG=info,phd=debug
1312026-05-07T23:53:41.207Z+ 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-05-07T23:53:41.207Z+ tee /tmp/phd-runner.log
1332026-05-07T23:53:41.389Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:41.362258328Z","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-05-07T23:53:41.414Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:41.396533688Z","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: 211, tv_nsec: 709374934 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-05-07T23:53:41.414Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:41.396644968Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-05-07T23:53:41.414Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:41.400007564Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"3c1708d86e10f0370807388a1efe092edd99d431"}
1372026-05-07T23:53:41.438Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:41.404968137Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/3c1708d86e10f0370807388a1efe092edd99d431/crucible-nightly.sha256.txt","timeout":"600s"}
1382026-05-07T23:53:41.637Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:41.624317294Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-05-07T23:53:42.126Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.113577784Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/81a050218eec93df73bb1690de419f0f63760f98/propolis-server.sha256.txt","timeout":"600s"}
1402026-05-07T23:53:42.277Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.264054851Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-05-07T23:53:42.277Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.264148238Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-05-07T23:53:42.277Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.264268044Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-05-07T23:53:42.277Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.264325673Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-05-07T23:53:42.278Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.264362353Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-05-07T23:53:42.278Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.264400254Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-05-07T23:53:42.302Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.266008734Z","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"}
1472026-05-07T23:53:42.302Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.26771196Z","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::can_migrate_from_base"}
1482026-05-07T23:53:42.302Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.268439296Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1492026-05-07T23:53:42.771Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.757989674Z","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::can_migrate_from_base"}
1502026-05-07T23:53:42.795Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:42.77104771Z","target":"phd_framework::artifacts::store","line":614,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1512026-05-07T23:53:49.591Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.579639212Z","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"}
1522026-05-07T23:53:49.617Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.580200252Z","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::can_migrate_from_base"}
1532026-05-07T23:53:49.618Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.594005147Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2.09M 25.3T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1542026-05-07T23:53:49.618Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.594740768Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-a9dbfd8d-d7cd-491f-a84f-366c960c478f\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1552026-05-07T23:53:49.642Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.620606638Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-a9dbfd8d-d7cd-491f-a84f-366c960c478f\", \"phd-artifacts/phd-clone-17a504cc-a66d-40ad-a9d3-eb5eab2aef2b\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1562026-05-07T23:53:49.666Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.641453001Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-17a504cc-a66d-40ad-a9d3-eb5eab2aef2b\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1572026-05-07T23:53:49.666Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.652657601Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-17a504cc-a66d-40ad-a9d3-eb5eab2aef2b 0B 25.3T 48.9M /phd-artifacts/phd-clone-17a504cc-a66d-40ad-a9d3-eb5eab2aef2b\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1582026-05-07T23:53:49.690Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.656291833Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1592026-05-07T23:53:49.690Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.65636964Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1602026-05-07T23:53:49.691Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.656430825Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/7a3c81cd34c2583665512749294bf525fd77d01472853e5719eb7116c508d054/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1612026-05-07T23:53:49.691Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:49.656496399Z","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/81a050218eec93df73bb1690de419f0f63760f98/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1622026-05-07T23:53:59.714Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:59.703330066Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/7a3c81cd34c2583665512749294bf525fd77d01472853e5719eb7116c508d054/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632026-05-07T23:53:59.714Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:53:59.703415107Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1642026-05-07T23:54:19.502Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:19.493187009Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/7a3c81cd34c2583665512749294bf525fd77d01472853e5719eb7116c508d054/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-05-07T23:54:19.502Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:19.493315832Z","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.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1662026-05-07T23:54:19.683Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 834","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:19.674984463Z","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"}
1672026-05-07T23:54:19.707Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:19.692678089Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1682026-05-07T23:54:19.731Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:19.704225711Z","target":"phd_framework::test_vm","line":459,"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","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1692026-05-07T23:54:19.731Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:19.706417803Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":30044,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1702026-05-07T23:54:20.301Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.292432381Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-05-07T23:54:20.346Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.296334985Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 1732fd76-eadb-4311-9ca9-de919b0f362f, name: \"phd-vm-1732fd76-eadb-4311-9ca9-de919b0f362f\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0059268e-6c01-4e77-9b0e-b25ea6078ddb, project_id: d090a8a9-d159-4a47-a7f8-f240c4c66d11, sled_id: c00b1a1a-a617-439b-b609-176aea40b728, sled_serial: \"c00b1a1a-a617-439b-b609-176aea40b728\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1722026-05-07T23:54:20.346Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.296881018Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1732026-05-07T23:54:20.346Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.296938747Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1742026-05-07T23:54:20.346Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.299082435Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":2,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1752026-05-07T23:54:20.346Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.299775266Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1762026-05-07T23:54:20.346Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.299869774Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1772026-05-07T23:54:20.346Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.299932914Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1782026-05-07T23:54:20.346Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.299981746Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1792026-05-07T23:54:20.347Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:20.300033304Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1802026-05-07T23:54:24.850Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.842207755Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":4541,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1812026-05-07T23:54:24.850Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.842295431Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1822026-05-07T23:54:24.874Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.843273482Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1832026-05-07T23:54:24.874Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.84339079Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1842026-05-07T23:54:24.874Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.843431196Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1852026-05-07T23:54:24.874Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.860900376Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":17,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1862026-05-07T23:54:24.874Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.860993326Z","target":"phd_framework::test_vm","line":851,"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"}
1872026-05-07T23:54:24.874Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.861186761Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1882026-05-07T23:54:24.874Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.861237125Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1892026-05-07T23:54:24.874Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.86193351Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1902026-05-07T23:54:24.902Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.894421524Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1912026-05-07T23:54:24.902Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.894568903Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1922026-05-07T23:54:24.926Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.894690052Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4594,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1932026-05-07T23:54:24.926Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.894987554Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1942026-05-07T23:54:24.926Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.89512307Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1952026-05-07T23:54:24.926Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.90600308Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1962026-05-07T23:54:24.926Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.906294871Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1972026-05-07T23:54:24.926Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.906396083Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
1982026-05-07T23:54:24.950Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.939189822Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1992026-05-07T23:54:24.950Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.939436318Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2002026-05-07T23:54:24.951Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.939538091Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2012026-05-07T23:54:24.974Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.950085933Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2022026-05-07T23:54:24.974Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.950362375Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2032026-05-07T23:54:24.974Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.950461082Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2042026-05-07T23:54:24.999Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.983668966Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2052026-05-07T23:54:24.999Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.983910593Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2062026-05-07T23:54:24.999Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.984005572Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2072026-05-07T23:54:25.023Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.994718186Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2082026-05-07T23:54:25.023Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.99501662Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2092026-05-07T23:54:25.023Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:24.995119755Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2102026-05-07T23:54:25.047Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.028114484Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2112026-05-07T23:54:25.047Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.02835028Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2122026-05-07T23:54:25.047Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.028444598Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2132026-05-07T23:54:25.047Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.03888103Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2142026-05-07T23:54:25.048Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.038991549Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2152026-05-07T23:54:25.048Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.039036644Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2162026-05-07T23:54:25.079Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.071626761Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2172026-05-07T23:54:25.103Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.071870291Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2182026-05-07T23:54:25.103Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.071965321Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2192026-05-07T23:54:25.103Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.083215841Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2202026-05-07T23:54:25.103Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.083435576Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2212026-05-07T23:54:25.103Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.083483216Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2222026-05-07T23:54:25.127Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.115962031Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2232026-05-07T23:54:25.128Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.116208557Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2242026-05-07T23:54:25.128Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.116312834Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2252026-05-07T23:54:25.151Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.126541422Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2262026-05-07T23:54:25.151Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.126777979Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2272026-05-07T23:54:25.151Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.126873179Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2282026-05-07T23:54:25.176Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.160098587Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2292026-05-07T23:54:25.176Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.1608084Z","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"}
2302026-05-07T23:54:25.176Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.160876066Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2312026-05-07T23:54:25.176Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.160915158Z","target":"phd_framework::test_vm","line":322,"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"}
2322026-05-07T23:54:25.176Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.161299172Z","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::can_migrate_from_base"}
2332026-05-07T23:54:25.176Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.161424431Z","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::can_migrate_from_base"}
2342026-05-07T23:54:25.176Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.161471099Z","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":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2352026-05-07T23:54:25.176Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.161532164Z","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"}
2362026-05-07T23:54:25.203Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 835","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.193900873Z","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"}
2372026-05-07T23:54:25.227Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.206849753Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":45,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2382026-05-07T23:54:25.227Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.20693308Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2392026-05-07T23:54:25.227Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.206993735Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"308770cd-8d84-4eeb-a9dd-ff2cda5b2f01","source":"migration_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2402026-05-07T23:54:25.228Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.20705466Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2412026-05-07T23:54:25.228Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.207657059Z","target":"phd_framework::test_vm","line":459,"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_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2422026-05-07T23:54:25.838Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.829696211Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 7900bba4-b572-4145-9985-6db2ca54519b, name: \"phd-vm-7900bba4-b572-4145-9985-6db2ca54519b\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0059268e-6c01-4e77-9b0e-b25ea6078ddb, project_id: d090a8a9-d159-4a47-a7f8-f240c4c66d11, sled_id: 1d2cfc39-26e8-499d-b00d-9b34e84f415f, sled_serial: \"1d2cfc39-26e8-499d-b00d-9b34e84f415f\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2432026-05-07T23:54:25.838Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:25.829901188Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","migration_id":"308770cd-8d84-4eeb-a9dd-ff2cda5b2f01","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2442026-05-07T23:54:28.359Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:28.3520252Z","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}}"}
2452026-05-07T23:54:28.384Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:28.361176173Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2462026-05-07T23:54:28.385Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:28.361244843Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","migration_id":"308770cd-8d84-4eeb-a9dd-ff2cda5b2f01","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":2530,"path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2472026-05-07T23:54:28.385Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:28.36421742Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2482026-05-07T23:54:28.385Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:28.365906162Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2492026-05-07T23:54:28.385Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:28.365982586Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2502026-05-07T23:54:28.385Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:28.369079628Z","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","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f"}
2512026-05-07T23:54:28.469Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:28.462588062Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":95,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2522026-05-07T23:54:28.496Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:28.464093307Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","elapsed_milliseconds":8769,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-05-07T23:54:31.166Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.159420512Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b","elapsed_milliseconds":2792,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-05-07T23:54:31.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.159834184Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2552026-05-07T23:54:31.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.159954702Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2562026-05-07T23:54:31.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.192987684Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2572026-05-07T23:54:31.215Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.193145642Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2582026-05-07T23:54:31.215Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.193432845Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2592026-05-07T23:54:31.215Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.193630178Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2602026-05-07T23:54:31.215Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.193679351Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10899}
2612026-05-07T23:54:31.216Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.193812743Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2622026-05-07T23:54:31.216Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.195174687Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2632026-05-07T23:54:31.577Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.569920047Z","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_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2642026-05-07T23:54:31.656Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.649845787Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2652026-05-07T23:54:31.657Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.649945613Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-17a504cc-a66d-40ad-a9d3-eb5eab2aef2b\"]","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2662026-05-07T23:54:31.683Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.676209473Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2672026-05-07T23:54:31.683Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.6762663Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-a9dbfd8d-d7cd-491f-a84f-366c960c478f\"]","verb":"destroy","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2682026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.69531114Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b","elapsed_milliseconds":501,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2692026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.695572664Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"7900bba4-b572-4145-9985-6db2ca54519b","elapsed_milliseconds":6487,"path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","target":"migration_from_base_lifecycle_0","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2702026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.695608372Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":501}
2712026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.695674847Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"1732fd76-eadb-4311-9ca9-de919b0f362f","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":6487,"path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"7900bba4-b572-4145-9985-6db2ca54519b"}
2722026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.695715474Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2732026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.69575534Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2742026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.695743387Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":49421,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2752026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.695793201Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2762026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.695959095Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2772026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.696058843Z","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::serial_history"}
2782026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.696119778Z","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"}
2792026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.696182277Z","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"}
2802026-05-07T23:54:31.707Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.696246658Z","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"}
2812026-05-07T23:54:31.731Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.706677309Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.00G 25.3T 1024M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2822026-05-07T23:54:31.732Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.706970022Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-c9bffbf8-4183-4199-b185-d54365f64e08\"]","path":"phd_tests::migrate::from_base::serial_history"}
2832026-05-07T23:54:31.757Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.727247036Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-c9bffbf8-4183-4199-b185-d54365f64e08\", \"phd-artifacts/phd-clone-c6a403ee-0782-40e6-8481-662fffb6436e\"]","path":"phd_tests::migrate::from_base::serial_history"}
2842026-05-07T23:54:31.757Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.745392007Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-c6a403ee-0782-40e6-8481-662fffb6436e\"]","verb":"list","path":"phd_tests::migrate::from_base::serial_history"}
2852026-05-07T23:54:31.781Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.757942524Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-c6a403ee-0782-40e6-8481-662fffb6436e 0B 25.3T 1024M /phd-artifacts/phd-clone-c6a403ee-0782-40e6-8481-662fffb6436e\n","path":"phd_tests::migrate::from_base::serial_history"}
2862026-05-07T23:54:31.781Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.758658507Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2872026-05-07T23:54:31.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.758725584Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
2882026-05-07T23:54:31.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.758789545Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/7a3c81cd34c2583665512749294bf525fd77d01472853e5719eb7116c508d054/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2892026-05-07T23:54:31.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.758852173Z","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/7a3c81cd34c2583665512749294bf525fd77d01472853e5719eb7116c508d054/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
2902026-05-07T23:54:31.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.758927085Z","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"}
2912026-05-07T23:54:31.805Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 844","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.794572164Z","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"}
2922026-05-07T23:54:31.830Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.808887229Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":50,"path":"phd_tests::migrate::from_base::serial_history"}
2932026-05-07T23:54:31.830Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.808981137Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
2942026-05-07T23:54:31.830Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:31.809742951Z","target":"phd_framework::test_vm","line":459,"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","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
2952026-05-07T23:54:32.664Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.657558769Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2962026-05-07T23:54:32.711Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.658332964Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 400f262b-7d09-43b4-9d4f-757609f3ef59, name: \"phd-vm-400f262b-7d09-43b4-9d4f-757609f3ef59\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: ab50a89f-8c8c-4f9e-8c23-51ccb352adb5, project_id: 83c81f0c-f37e-4567-a4de-54de87105ed5, sled_id: ab048804-1205-4d11-bca5-9be92011abf6, sled_serial: \"ab048804-1205-4d11-bca5-9be92011abf6\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
2972026-05-07T23:54:32.711Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.658472558Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
2982026-05-07T23:54:32.711Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.658524275Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
2992026-05-07T23:54:32.711Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.659482373Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3002026-05-07T23:54:32.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.659562925Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3012026-05-07T23:54:32.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.65961878Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","timeout_duration":"300s","path":"phd_tests::migrate::from_base::serial_history"}
3022026-05-07T23:54:32.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.65966595Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
3032026-05-07T23:54:32.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.659710033Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3042026-05-07T23:54:32.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:32.659758264Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3052026-05-07T23:54:37.198Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.191689998Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4531,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3062026-05-07T23:54:37.198Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.191779487Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
3072026-05-07T23:54:37.222Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.1919609Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3082026-05-07T23:54:37.222Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.192021154Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3092026-05-07T23:54:37.223Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.192073733Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3102026-05-07T23:54:37.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.220034306Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":27,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3112026-05-07T23:54:37.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.220181621Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3122026-05-07T23:54:37.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.220572205Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3132026-05-07T23:54:37.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.220631126Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3142026-05-07T23:54:37.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.220673146Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3152026-05-07T23:54:37.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.253357429Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3162026-05-07T23:54:37.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.2534639Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3172026-05-07T23:54:37.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.253535004Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4593,"path":"phd_tests::migrate::from_base::serial_history"}
3182026-05-07T23:54:37.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.253699505Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3192026-05-07T23:54:37.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.253747786Z","target":"phd_framework::test_vm","line":924,"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","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3202026-05-07T23:54:37.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.263999489Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3212026-05-07T23:54:37.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.26411655Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3222026-05-07T23:54:37.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.264165673Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3232026-05-07T23:54:37.303Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.29745021Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3242026-05-07T23:54:37.327Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.297680699Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3252026-05-07T23:54:37.327Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.297737845Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3262026-05-07T23:54:37.327Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.308365724Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3272026-05-07T23:54:37.327Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.308665482Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3282026-05-07T23:54:37.328Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.308757726Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3292026-05-07T23:54:37.352Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.340640454Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3302026-05-07T23:54:37.352Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.346053022Z","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"}
3312026-05-07T23:54:37.352Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.346134977Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3322026-05-07T23:54:37.352Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.346177618Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
3332026-05-07T23:54:37.352Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.346233734Z","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::serial_history"}
3342026-05-07T23:54:37.352Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.346280492Z","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::serial_history"}
3352026-05-07T23:54:37.376Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.346350104Z","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"}
3362026-05-07T23:54:37.400Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 845","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.379505757Z","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"}
3372026-05-07T23:54:37.400Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.392636359Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":46,"path":"phd_tests::migrate::from_base::serial_history"}
3382026-05-07T23:54:37.400Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.392709648Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3392026-05-07T23:54:37.400Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.392766004Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"fc3b4769-13a8-4548-9185-e0be8d10a075","source":"migration_serial_history_base","source_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3402026-05-07T23:54:37.400Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.39282184Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3412026-05-07T23:54:37.400Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.39328259Z","target":"phd_framework::test_vm","line":459,"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":"400f262b-7d09-43b4-9d4f-757609f3ef59","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3422026-05-07T23:54:37.851Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.844553972Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 98fcf8f3-76f7-4dee-acf6-c738a3a50281, name: \"phd-vm-98fcf8f3-76f7-4dee-acf6-c738a3a50281\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: ab50a89f-8c8c-4f9e-8c23-51ccb352adb5, project_id: 83c81f0c-f37e-4567-a4de-54de87105ed5, sled_id: ee05f966-e819-475a-add9-45fac4912529, sled_serial: \"ee05f966-e819-475a-add9-45fac4912529\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_serial_history_base","source_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3432026-05-07T23:54:37.851Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:37.844747147Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","migration_id":"fc3b4769-13a8-4548-9185-e0be8d10a075"}
3442026-05-07T23:54:40.557Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:40.551284412Z","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}}"}
3452026-05-07T23:54:41.834Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.828275528Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3462026-05-07T23:54:41.834Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.828352644Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3982,"source":"migration_serial_history_base","source_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","migration_id":"fc3b4769-13a8-4548-9185-e0be8d10a075"}
3472026-05-07T23:54:41.858Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.830586664Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3482026-05-07T23:54:41.858Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.832502465Z","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","path":"phd_tests::migrate::from_base::serial_history","vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59"}
3492026-05-07T23:54:41.927Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.92207371Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":91,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3502026-05-07T23:54:41.951Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.922423424Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10111,"vm_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3512026-05-07T23:54:41.951Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.925375103Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3522026-05-07T23:54:41.951Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.925636136Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3532026-05-07T23:54:41.951Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.925789416Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9266}
3542026-05-07T23:54:41.951Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.925790478Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3552026-05-07T23:54:41.951Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.925932998Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3562026-05-07T23:54:41.952Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:41.927430785Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3572026-05-07T23:54:42.610Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.604215164Z","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","path":"phd_tests::migrate::from_base::serial_history","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3582026-05-07T23:54:42.688Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.682395529Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3592026-05-07T23:54:42.688Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.682496981Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-c6a403ee-0782-40e6-8481-662fffb6436e\"]","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3602026-05-07T23:54:42.714Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.709462597Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3612026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.709519655Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-c9bffbf8-4183-4199-b185-d54365f64e08\"]","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3622026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.727557449Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":801,"vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3632026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.727722121Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":801}
3642026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.727800499Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3652026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.727850393Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3662026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.72781188Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":5333,"source":"migration_serial_history_base","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","vm_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281"}
3672026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.727889417Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3682026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.727902361Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":5334,"source":"migration_serial_history_base","source_id":"400f262b-7d09-43b4-9d4f-757609f3ef59","target_id":"98fcf8f3-76f7-4dee-acf6-c738a3a50281","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3692026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.72796004Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":11029,"path":"phd_tests::migrate::from_base::serial_history"}
3702026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.728032958Z","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"}
3712026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.728127377Z","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"}
3722026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.728190175Z","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"}
3732026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.728255799Z","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"}
3742026-05-07T23:54:42.739Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.728323026Z","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::migration_from_base_and_back"}
3752026-05-07T23:54:42.763Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.739917687Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.00G 25.3T 1024M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-05-07T23:54:42.763Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.740103408Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-45ff428c-15f9-4910-b365-f5b1fae34f15\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-05-07T23:54:42.787Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.761393178Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-45ff428c-15f9-4910-b365-f5b1fae34f15\", \"phd-artifacts/phd-clone-12a88dd4-ead2-4c02-96f5-1c90bd0c1e22\"]","verb":"clone","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-05-07T23:54:42.787Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.778401128Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-12a88dd4-ead2-4c02-96f5-1c90bd0c1e22\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-05-07T23:54:42.812Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.789995766Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-12a88dd4-ead2-4c02-96f5-1c90bd0c1e22 0B 25.3T 1024M /phd-artifacts/phd-clone-12a88dd4-ead2-4c02-96f5-1c90bd0c1e22\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-05-07T23:54:42.812Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.790647127Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3812026-05-07T23:54:42.812Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.790707962Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-05-07T23:54:42.812Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.790769739Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/7a3c81cd34c2583665512749294bf525fd77d01472853e5719eb7116c508d054/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-05-07T23:54:42.812Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.790829562Z","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/7a3c81cd34c2583665512749294bf525fd77d01472853e5719eb7116c508d054/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-05-07T23:54:42.812Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.790900446Z","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"}
3852026-05-07T23:54:42.836Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 854","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.824255477Z","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"}
3862026-05-07T23:54:42.860Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.83885239Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":48}
3872026-05-07T23:54:42.860Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.838966906Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3882026-05-07T23:54:42.860Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:42.839636402Z","target":"phd_framework::test_vm","line":459,"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":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3892026-05-07T23:54:43.455Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.448195872Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3902026-05-07T23:54:43.481Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.449075157Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: eaebf8e8-b017-46a5-9076-f3c77c728e56, name: \"phd-vm-eaebf8e8-b017-46a5-9076-f3c77c728e56\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 38fd6d2a-1a13-4251-9ab5-c9242e2e640e, project_id: 553a0bde-c883-4bda-b3a3-1c199aa06d20, sled_id: 64275ec4-c181-4e7d-bbd7-2a5d004ded03, sled_serial: \"64275ec4-c181-4e7d-bbd7-2a5d004ded03\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3912026-05-07T23:54:43.481Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.449220171Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3922026-05-07T23:54:43.481Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.449271167Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3932026-05-07T23:54:43.481Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.450294521Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":1,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3942026-05-07T23:54:43.481Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.450372889Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3952026-05-07T23:54:43.481Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.450426461Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-05-07T23:54:43.481Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.450471476Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972026-05-07T23:54:43.481Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.450512964Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3982026-05-07T23:54:43.481Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:43.450576414Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3992026-05-07T23:54:47.961Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.956345341Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":4504,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4002026-05-07T23:54:47.961Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.956436554Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012026-05-07T23:54:47.986Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.956615482Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4022026-05-07T23:54:47.986Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.95666748Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4032026-05-07T23:54:47.986Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.956710261Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4042026-05-07T23:54:47.986Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.973713187Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":16,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4052026-05-07T23:54:47.986Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.973794124Z","target":"phd_framework::test_vm","line":851,"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"}
4062026-05-07T23:54:47.987Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.973961061Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4072026-05-07T23:54:47.987Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.97401291Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4082026-05-07T23:54:47.987Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:47.974051279Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4092026-05-07T23:54:48.012Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.007330286Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":33,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4102026-05-07T23:54:48.012Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.007440203Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4112026-05-07T23:54:48.012Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.007513632Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4556}
4122026-05-07T23:54:48.037Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.00783511Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4132026-05-07T23:54:48.037Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.007940709Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4142026-05-07T23:54:48.037Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.018936969Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4152026-05-07T23:54:48.037Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.019197191Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4162026-05-07T23:54:48.037Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.019291529Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4172026-05-07T23:54:48.063Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.051515973Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-05-07T23:54:48.064Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.051808784Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4192026-05-07T23:54:48.064Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.051905829Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4202026-05-07T23:54:48.089Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.062504488Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4212026-05-07T23:54:48.089Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.062732967Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4222026-05-07T23:54:48.090Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.062837274Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4232026-05-07T23:54:48.114Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.096164924Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":33,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4242026-05-07T23:54:48.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.096405779Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4252026-05-07T23:54:48.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.096458739Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4262026-05-07T23:54:48.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.108025537Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":11,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4272026-05-07T23:54:48.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.108309774Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4282026-05-07T23:54:48.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.108366571Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4292026-05-07T23:54:48.146Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.141327255Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4302026-05-07T23:54:48.172Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.141634636Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4312026-05-07T23:54:48.172Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.141740967Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4322026-05-07T23:54:48.172Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.152946933Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":11,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4332026-05-07T23:54:48.173Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.153071568Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4342026-05-07T23:54:48.173Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.153121873Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4352026-05-07T23:54:48.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.185337731Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4362026-05-07T23:54:48.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.185465703Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4372026-05-07T23:54:48.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.185516389Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4382026-05-07T23:54:48.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.19698972Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":11,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4392026-05-07T23:54:48.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.197103164Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4402026-05-07T23:54:48.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.197152848Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4412026-05-07T23:54:48.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.229827551Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4422026-05-07T23:54:48.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.229951956Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4432026-05-07T23:54:48.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.230000358Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4442026-05-07T23:54:48.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.24034233Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4452026-05-07T23:54:48.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.240459462Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4462026-05-07T23:54:48.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.240506721Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4472026-05-07T23:54:48.278Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.273285072Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4482026-05-07T23:54:48.278Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.273345827Z","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"}
4492026-05-07T23:54:48.278Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.273416611Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-05-07T23:54:48.278Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.273459782Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-05-07T23:54:48.306Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.273519054Z","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"}
4522026-05-07T23:54:48.306Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.273570602Z","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":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-05-07T23:54:48.306Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.273664639Z","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_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-05-07T23:54:48.331Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 855","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.303721506Z","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"}
4552026-05-07T23:54:48.331Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.317141092Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":43}
4562026-05-07T23:54:48.331Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.317236185Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56"}
4572026-05-07T23:54:48.331Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.317302431Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"f498d1cb-c91a-46a4-bcb3-d24aabacadee","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56"}
4582026-05-07T23:54:48.331Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.317362949Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","vm":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_0","vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56"}
4592026-05-07T23:54:48.331Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.318056564Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","vm":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_0","vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56"}
4602026-05-07T23:54:48.978Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.973547013Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: b7c9d4c8-57fa-4756-a557-48c634832dba, name: \"phd-vm-b7c9d4c8-57fa-4756-a557-48c634832dba\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 38fd6d2a-1a13-4251-9ab5-c9242e2e640e, project_id: 553a0bde-c883-4bda-b3a3-1c199aa06d20, sled_id: 273f11d5-dca5-4224-b68c-f3e97859aa35, sled_serial: \"273f11d5-dca5-4224-b68c-f3e97859aa35\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","vm":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_0","vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56"}
4612026-05-07T23:54:48.978Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:48.97376769Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","migration_id":"f498d1cb-c91a-46a4-bcb3-d24aabacadee","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56"}
4622026-05-07T23:54:51.686Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:51.681466396Z","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}}"}
4632026-05-07T23:54:53.121Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:53.115660735Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56"}
4642026-05-07T23:54:53.122Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:53.115740105Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","migration_id":"f498d1cb-c91a-46a4-bcb3-d24aabacadee","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":4141,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56"}
4652026-05-07T23:54:53.146Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:53.117759828Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4662026-05-07T23:54:53.146Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:53.117984098Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4672026-05-07T23:54:53.146Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:53.118038144Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4682026-05-07T23:54:53.146Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:53.119972693Z","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":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4692026-05-07T23:54:53.223Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:53.212885597Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":94,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4702026-05-07T23:54:53.223Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:53.213222043Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":10372,"vm_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4712026-05-07T23:54:54.310Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.306691997Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":1188,"vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4722026-05-07T23:54:54.334Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.307067609Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4732026-05-07T23:54:54.335Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.307178933Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4742026-05-07T23:54:54.360Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.340341182Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":33,"vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4752026-05-07T23:54:54.360Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.340519028Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__BASE_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762026-05-07T23:54:54.360Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.340651058Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772026-05-07T23:54:54.360Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.340732662Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_1","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-05-07T23:54:54.360Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.340839223Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/7a3c81cd34c2583665512749294bf525fd77d01472853e5719eb7116c508d054/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-05-07T23:54:54.360Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.34093278Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9004","server_path":"\"/phd-artifacts/7a3c81cd34c2583665512749294bf525fd77d01472853e5719eb7116c508d054/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-05-07T23:54:54.361Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.341077864Z","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_1.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-05-07T23:54:54.387Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 857","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.373969642Z","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"}
4822026-05-07T23:54:54.411Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.387264531Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":46}
4832026-05-07T23:54:54.411Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.387356275Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba"}
4842026-05-07T23:54:54.411Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.387437208Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"7fa699cc-b3a9-4446-a7eb-9d28f49919fc","timeout_duration":"45s","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba"}
4852026-05-07T23:54:54.411Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.38752327Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","vm":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_1","vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba"}
4862026-05-07T23:54:54.411Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.388083089Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","vm":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_1","vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba"}
4872026-05-07T23:54:54.952Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.948526138Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 1b672344-48e5-4c18-bcc4-1162f6cd0a01, name: \"phd-vm-1b672344-48e5-4c18-bcc4-1162f6cd0a01\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 38fd6d2a-1a13-4251-9ab5-c9242e2e640e, project_id: 553a0bde-c883-4bda-b3a3-1c199aa06d20, sled_id: 382586e0-9513-4b49-9bf8-94fbedcf4544, sled_serial: \"382586e0-9513-4b49-9bf8-94fbedcf4544\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","vm":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_1","vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba"}
4882026-05-07T23:54:54.952Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:54.948703123Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","migration_id":"7fa699cc-b3a9-4446-a7eb-9d28f49919fc","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba"}
4892026-05-07T23:54:57.696Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:57.692309052Z","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}}"}
4902026-05-07T23:54:58.047Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.044106583Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba"}
4912026-05-07T23:54:58.047Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.04418166Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","migration_id":"7fa699cc-b3a9-4446-a7eb-9d28f49919fc","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":3094,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba"}
4922026-05-07T23:54:58.072Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.046293043Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4932026-05-07T23:54:58.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.046551131Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4942026-05-07T23:54:58.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.046617026Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4952026-05-07T23:54:58.072Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.047689914Z","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":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4962026-05-07T23:54:58.132Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.129395479Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":82,"vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4972026-05-07T23:54:58.157Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.129595227Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","vm_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":9810,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4982026-05-07T23:54:58.157Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.129680438Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","elapsed_milliseconds":9810,"target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"eaebf8e8-b017-46a5-9076-f3c77c728e56"}
4992026-05-07T23:54:58.157Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.129891377Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":83,"vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5002026-05-07T23:54:58.157Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.130186975Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5012026-05-07T23:54:58.157Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.130269491Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5022026-05-07T23:54:58.181Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.159436036Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":29,"vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5032026-05-07T23:54:58.181Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.15957583Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5042026-05-07T23:54:58.181Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.159704643Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5052026-05-07T23:54:58.181Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.15978731Z","target":"phd_framework::test_vm","line":322,"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"}
5062026-05-07T23:54:58.181Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.159892719Z","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"}
5072026-05-07T23:54:58.181Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.159980455Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-05-07T23:54:58.181Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.16009439Z","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"}
5092026-05-07T23:54:58.205Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 859","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.193804611Z","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"}
5102026-05-07T23:54:58.228Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.208323487Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":48}
5112026-05-07T23:54:58.228Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.208440468Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01"}
5122026-05-07T23:54:58.228Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.208523285Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"9ad29bd7-5272-459b-916e-74f35d6d4089","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01"}
5132026-05-07T23:54:58.228Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.20859982Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","vm":"migration_from_base_and_back_lifecycle_2","target":"migration_from_base_and_back_lifecycle_2","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01"}
5142026-05-07T23:54:58.229Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.209215323Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","vm":"migration_from_base_and_back_lifecycle_2","target":"migration_from_base_and_back_lifecycle_2","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01"}
5152026-05-07T23:54:58.980Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.976424431Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 358c85c7-c802-4cf0-b959-1e444a30ce6f, name: \"phd-vm-358c85c7-c802-4cf0-b959-1e444a30ce6f\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 38fd6d2a-1a13-4251-9ab5-c9242e2e640e, project_id: 553a0bde-c883-4bda-b3a3-1c199aa06d20, sled_id: 63c2e06e-2d9d-4864-b1c3-30bd6749e04c, sled_serial: \"63c2e06e-2d9d-4864-b1c3-30bd6749e04c\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","vm":"migration_from_base_and_back_lifecycle_2","target":"migration_from_base_and_back_lifecycle_2","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01"}
5162026-05-07T23:54:58.980Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:54:58.976627705Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","migration_id":"9ad29bd7-5272-459b-916e-74f35d6d4089","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01"}
5172026-05-07T23:55:01.764Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:01.759896344Z","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}}"}
5182026-05-07T23:55:02.846Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.841971374Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01"}
5192026-05-07T23:55:02.846Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.842049762Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","migration_id":"9ad29bd7-5272-459b-916e-74f35d6d4089","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":3864,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01"}
5202026-05-07T23:55:02.871Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.844380637Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5212026-05-07T23:55:02.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.844596963Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5222026-05-07T23:55:02.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.844650435Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5232026-05-07T23:55:02.871Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.846517454Z","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_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5242026-05-07T23:55:02.938Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.936098192Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":91,"vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5252026-05-07T23:55:02.963Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.936402377Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","vm_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":8547,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5262026-05-07T23:55:02.963Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.936529387Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","elapsed_milliseconds":8547,"target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"b7c9d4c8-57fa-4756-a557-48c634832dba"}
5272026-05-07T23:55:02.964Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.936592156Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":91,"vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5282026-05-07T23:55:02.964Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.936995869Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5292026-05-07T23:55:02.964Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.937099525Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5302026-05-07T23:55:02.989Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.970222634Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":33,"vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5312026-05-07T23:55:02.989Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.970458421Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5322026-05-07T23:55:02.989Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.970731918Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5332026-05-07T23:55:02.989Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.970934571Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":19518}
5342026-05-07T23:55:02.989Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.971391003Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5352026-05-07T23:55:02.989Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.971490351Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5362026-05-07T23:55:02.989Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:02.97243144Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5372026-05-07T23:55:03.361Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.358580836Z","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_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5382026-05-07T23:55:03.438Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.435173969Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5392026-05-07T23:55:03.438Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.435280801Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-12a88dd4-ead2-4c02-96f5-1c90bd0c1e22\"]","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5402026-05-07T23:55:03.464Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.462220128Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5412026-05-07T23:55:03.489Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.462277456Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-45ff428c-15f9-4910-b365-f5b1fae34f15\"]","verb":"destroy","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5422026-05-07T23:55:03.489Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.48104Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":510,"vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5432026-05-07T23:55:03.489Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.481230761Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","vm_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":5271,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5442026-05-07T23:55:03.489Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.48132528Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":509}
5452026-05-07T23:55:03.489Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.481340418Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"358c85c7-c802-4cf0-b959-1e444a30ce6f","elapsed_milliseconds":5271,"target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"1b672344-48e5-4c18-bcc4-1162f6cd0a01"}
5462026-05-07T23:55:03.490Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.481398438Z","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":20749}
5472026-05-07T23:55:03.490Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.481437552Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5482026-05-07T23:55:03.490Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.481481525Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5492026-05-07T23:55:03.490Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 81.20s
5502026-05-07T23:55:03.490Z
5512026-05-07T23:55:03.490Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":829,"time":"2026-05-07T23:55:03.483069606Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5522026-05-07T23:55:03.597Z
5532026-05-07T23:55:03.621Zreal 1:22.279626112
5542026-05-07T23:55:03.621Zuser 44.971010351
5552026-05-07T23:55:03.621Zsys 20.191824867
5562026-05-07T23:55:03.621Ztrap 0.007016642
5572026-05-07T23:55:03.621Ztflt 0.004110159
5582026-05-07T23:55:03.621Zdflt 0.003803501
5592026-05-07T23:55:03.621Zkflt 0.000000000
5602026-05-07T23:55:03.621Zlock 3:14:46.109046132
5612026-05-07T23:55:03.621Zslp 4:14.889553138
5622026-05-07T23:55:03.621Zlat 1.809132190
5632026-05-07T23:55:03.621Zstop 44.727798388
5642026-05-07T23:55:03.622Z+ failcount=0
5652026-05-07T23:55:03.622Z+ set -e
5662026-05-07T23:55:03.622Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5672026-05-07T23:55:03.622ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5682026-05-07T23:55:03.622Za ./ 0K
5692026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5702026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 137K
5712026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5722026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5732026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 143K
5742026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5752026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::serial_history/ 0K
5762026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 139K
5772026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5782026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5792026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 144K
5802026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5812026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5822026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 138K
5832026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5842026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5852026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 231K
5862026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5872026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 231K
5882026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5892026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 144K
5902026-05-07T23:55:03.622Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5912026-05-07T23:55:03.647Z+ exitcode=0
5922026-05-07T23:55:03.647Z+ '[' 0 -eq 0 ']'
5932026-05-07T23:55:03.647Z+ echo
5942026-05-07T23:55:03.647Z+ echo 'ALL TESTS PASSED'
5952026-05-07T23:55:03.647Z
5962026-05-07T23:55:03.647ZALL TESTS PASSED
5972026-05-07T23:55:03.647Z
5982026-05-07T23:55:03.647Z+ echo
5992026-05-07T23:55:03.647Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6002026-05-07T23:55:03.647Z+ read
6012026-05-07T23:55:03.647Z+ exit 0
6022026-05-07T23:55:03.647Zprocess exited: duration 123530 ms, exit code 0
 
6032026-05-07T23:55:03.700Zfound 2 output files
6042026-05-07T23:55:03.700Zuploading: /tmp/phd-runner.log (184406 bytes)
6052026-05-07T23:55:04.841Zuploaded: /tmp/phd-runner.log
6062026-05-07T23:55:04.865Zuploading: /tmp/phd-tmp-files.tar.gz (106349 bytes)
6072026-05-07T23:55:06.022Zuploaded: /tmp/phd-tmp-files.tar.gz