01KR3KMD6ZHBMXJ3RJHS2JX3NW: 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: 01KR3KMNFG09AMJT3PWJE6FKXT

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-05-08T11:05:46.133Zjob dependencies complete; ready to run (waiting for 10 m 21 s)
22026-05-08T11:25:39.060Zjob assigned to worker 01KR3N64P86FK23M23RMKN5TB4 [factory edgar, gimlet/BRM42220060/543] (queued for 19 m 52 s)
32026-05-08T11:25:39.502Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-05-08T11:25:39.529Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-05-08T11:25:39.553Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-05-08T11:25:39.578Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-05-08T11:25:39.578Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-05-08T11:25:45.152Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-05-08T11:25:45.153Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-05-08T11:25:45.201Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-05-08T11:25:45.201Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-05-08T11:25:56.460Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-05-08T11:25:56.460Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-05-08T11:26:04.142Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-05-08T11:26:04.142Zstarting task 0: "setup"
162026-05-08T11:26:04.166Z++ uname -s
172026-05-08T11:26:04.167Z+ kern=SunOS
182026-05-08T11:26:04.167Z+ build_user=build
192026-05-08T11:26:04.167Z+ build_uid=12345
202026-05-08T11:26:04.167Z+ work_dir=/work
212026-05-08T11:26:04.167Z+ input_dir=/input
222026-05-08T11:26:04.167Z+ [[ 0 == 12345 ]]
232026-05-08T11:26:04.167Z+ case "$kern" in
242026-05-08T11:26:04.167Z+ groupadd -g 12345 build
252026-05-08T11:26:04.191Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-05-08T11:26:06.176Z+ zfs create -o mountpoint=/work rpool/work
272026-05-08T11:26:06.291Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-05-08T11:26:06.315Z+ home_fs=
292026-05-08T11:26:06.315Z+ [[ '' == autofs ]]
302026-05-08T11:26:06.315Z+ mkdir -p /home/build
312026-05-08T11:26:06.315Z+ chown build:build /home/build /work
322026-05-08T11:26:08.305Z+ chmod 0700 /home/build /work
332026-05-08T11:26:08.330Zprocess exited: duration 4168 ms, exit code 0
 
342026-05-08T11:26:08.379Zstarting task 1: "authentication"
352026-05-08T11:26:08.448Zprocess exited: duration 68 ms, exit code 0
 
362026-05-08T11:26:08.496Zstarting task 2: "build"
372026-05-08T11:26:08.524Z+ indir=/input
382026-05-08T11:26:08.524Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-05-08T11:26:08.524Z+ phddir=/work/phd-test
402026-05-08T11:26:08.524Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-05-08T11:26:08.548Z++ pilot local disk list -H -o type,disk
422026-05-08T11:26:08.548Z++ grep -v M.2
432026-05-08T11:26:08.548Z++ cut -f 2
442026-05-08T11:26:08.602Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC586d0 c9t0014EE81000BC57Cd0 c10t0014EE81000BC3CCd0 c11t0014EE81000BC478d0 c4t0014EE81000BC5BBd0 c3t0014EE81000BC247d0 c2t0014EE81000BC649d0 c6t0014EE81000BC634d0 c5t0014EE81000BC0B1d0
452026-05-08T11:26:08.871Z+ artifactdir=/phd-artifacts
462026-05-08T11:26:08.871Z+ banner Inputs
472026-05-08T11:26:08.896Z ###
482026-05-08T11:26:08.896Z # # # ##### # # ##### ####
492026-05-08T11:26:08.896Z # ## # # # # # # #
502026-05-08T11:26:08.896Z # # # # # # # # # ####
512026-05-08T11:26:08.896Z # # # # ##### # # # #
522026-05-08T11:26:08.896Z # # ## # # # # # #
532026-05-08T11:26:08.896Z ### # # # #### # ####
542026-05-08T11:26:08.896Z
552026-05-08T11:26:08.896Z+ find /input -ls
562026-05-08T11:26:08.896Z 34 1 drwxr-xr-x 3 root root 3 May 8 11:25 /input
572026-05-08T11:26:08.896Z 2 1 drwxr-xr-x 3 root root 3 May 8 11:25 /input/phd-build
582026-05-08T11:26:08.896Z 3 2 drwxr-xr-x 2 root root 8 May 8 11:25 /input/phd-build/out
592026-05-08T11:26:08.896Z 257 119142 -rw-r--r-- 1 root root 121925766 May 8 11:25 /input/phd-build/out/phd-runner.tar.gz
602026-05-08T11:26:08.896Z 512 168841 -rw-r--r-- 1 root root 172903935 May 8 11:26 /input/phd-build/out/propolis-tests-debug.tar.gz
612026-05-08T11:26:08.896Z 384 1 -rw-r--r-- 1 root root 65 May 8 11:25 /input/phd-build/out/propolis-server-debug.sha256.txt
622026-05-08T11:26:08.896Z 385 207499 -rw-r--r-- 1 root root 212530385 May 8 11:25 /input/phd-build/out/propolis-server-debug.tar.gz
632026-05-08T11:26:08.896Z 128 2 -rw-r--r-- 1 root root 2573 May 8 11:25 /input/phd-build/out/phd-run-with-args.sh
642026-05-08T11:26:08.896Z 256 1 -rw-r--r-- 1 root root 65 May 8 11:25 /input/phd-build/out/phd-runner.sha256.txt
652026-05-08T11:26:08.896Z+ rm -rf /work/phd-test
662026-05-08T11:26:08.896Z+ mkdir /work/phd-test
672026-05-08T11:26:08.896Z+ for p in $indir/$indir_suffix
682026-05-08T11:26:08.896Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-05-08T11:26:12.023ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-05-08T11:26:12.023Zx phd-runner, 432316896 bytes, 844369 tape blocks
712026-05-08T11:26:12.023Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-05-08T11:26:12.047Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-05-08T11:26:15.037Z+ for f in $(tar tf "$p")
742026-05-08T11:26:15.037Z+ chmod +x /work/phd-test/phd-runner
752026-05-08T11:26:15.062Z+ for f in $(tar tf "$p")
762026-05-08T11:26:15.062Z+ chmod +x /work/phd-test/artifacts.toml
772026-05-08T11:26:15.062Z+ for p in $indir/$indir_suffix
782026-05-08T11:26:15.062Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-05-08T11:26:25.227ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-05-08T11:26:25.227Zx propolis-server, 809088848 bytes, 1580252 tape blocks
812026-05-08T11:26:25.251Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-05-08T11:26:30.790Z+ for f in $(tar tf "$p")
832026-05-08T11:26:30.790Z+ chmod +x /work/phd-test/propolis-server
842026-05-08T11:26:30.815Z+ for p in $indir/$indir_suffix
852026-05-08T11:26:30.815Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-05-08T11:26:44.701ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-05-08T11:26:44.702Zx target/debug/deps/propolis-a70121243652f668, 657950592 bytes, 1285060 tape blocks
882026-05-08T11:26:44.726Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-05-08T11:26:48.768Z+ for f in $(tar tf "$p")
902026-05-08T11:26:48.768Z+ chmod +x /work/phd-test/target/debug/deps/propolis-a70121243652f668
912026-05-08T11:26:48.793Z+ ls /work/phd-test
922026-05-08T11:26:48.793Zartifacts.toml
932026-05-08T11:26:48.793Zphd-runner
942026-05-08T11:26:48.793Zpropolis-server
952026-05-08T11:26:48.793Ztarget
962026-05-08T11:26:48.793Z+ banner Setup
972026-05-08T11:26:48.793Z #####
982026-05-08T11:26:48.793Z# # ###### ##### # # #####
992026-05-08T11:26:48.793Z# # # # # # #
1002026-05-08T11:26:48.793Z ##### ##### # # # # #
1012026-05-08T11:26:48.793Z # # # # # #####
1022026-05-08T11:26:48.793Z# # # # # # #
1032026-05-08T11:26:48.793Z ##### ###### # #### #
1042026-05-08T11:26:48.793Z
1052026-05-08T11:26:48.793Z+ tmpdir=/tmp/propolis-phd
1062026-05-08T11:26:48.793Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-05-08T11:26:48.793Z+ mkdir /tmp/propolis-phd
1082026-05-08T11:26:48.793Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-05-08T11:26:49.253Z+ banner Tests
1102026-05-08T11:26:49.278Z#######
1112026-05-08T11:26:49.278Z # ###### #### ##### ####
1122026-05-08T11:26:49.278Z # # # # #
1132026-05-08T11:26:49.278Z # ##### #### # ####
1142026-05-08T11:26:49.278Z # # # # #
1152026-05-08T11:26:49.278Z # # # # # # #
1162026-05-08T11:26:49.278Z # ###### #### # ####
1172026-05-08T11:26:49.278Z
1182026-05-08T11:26:49.278Z+ runner=/work/phd-test/phd-runner
1192026-05-08T11:26:49.278Z+ artifacts=/work/phd-test/artifacts.toml
1202026-05-08T11:26:49.278Z+ propolis=/work/phd-test/propolis-server
1212026-05-08T11:26:49.278Z+ ls /work/phd-test/phd-runner
1222026-05-08T11:26:49.278Z/work/phd-test/phd-runner
1232026-05-08T11:26:49.278Z+ ls /work/phd-test/artifacts.toml
1242026-05-08T11:26:49.278Z/work/phd-test/artifacts.toml
1252026-05-08T11:26:49.278Z+ ls /work/phd-test/propolis-server
1262026-05-08T11:26:49.278Z/work/phd-test/propolis-server
1272026-05-08T11:26:49.278Z+ 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-08T11:26:49.278Z+ set +e
1292026-05-08T11:26:49.278Z+ RUST_BACKTRACE=1
1302026-05-08T11:26:49.278Z+ RUST_LOG=info,phd=debug
1312026-05-08T11:26:49.278Z+ 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-08T11:26:49.278Z+ tee /tmp/phd-runner.log
1332026-05-08T11:26:49.455Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:49.431865794Z","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-08T11:26:49.483Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:49.462653468Z","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: 213, tv_nsec: 172478548 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-05-08T11:26:49.483Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:49.462742998Z","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-08T11:26:49.483Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:49.465494686Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"3c1708d86e10f0370807388a1efe092edd99d431"}
1372026-05-08T11:26:49.484Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:49.469579627Z","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-08T11:26:49.686Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:49.673134665Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-05-08T11:26:50.232Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.218569523Z","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/2a49b9cfb8d4793fd99b286657792aa19f0f70c5/propolis-server.sha256.txt","timeout":"600s"}
1402026-05-08T11:26:50.382Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.368240475Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-05-08T11:26:50.382Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.368322029Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-05-08T11:26:50.382Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.368442257Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-05-08T11:26:50.382Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.368508963Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-05-08T11:26:50.382Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.368540683Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-05-08T11:26:50.382Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.368571391Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-05-08T11:26:50.407Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.370588679Z","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-08T11:26:50.407Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.372301771Z","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-08T11:26:50.407Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.373037662Z","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-08T11:26:50.894Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.881007478Z","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-08T11:26:50.919Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:50.89483461Z","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-08T11:26:57.805Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.792021463Z","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-08T11:26:57.829Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.792610107Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1532026-05-08T11:26:57.829Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.805986601Z","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-08T11:26:57.829Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.807178336Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-858b10e8-f48f-407c-b75a-a4fbe7c52a76\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1552026-05-08T11:26:57.854Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.830557883Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-858b10e8-f48f-407c-b75a-a4fbe7c52a76\", \"phd-artifacts/phd-clone-b9b86fc4-0d20-4d90-ab09-31e5985c32f7\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1562026-05-08T11:26:57.878Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.847262847Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-b9b86fc4-0d20-4d90-ab09-31e5985c32f7\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1572026-05-08T11:26:57.878Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.85852479Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-b9b86fc4-0d20-4d90-ab09-31e5985c32f7 0B 25.3T 48.9M /phd-artifacts/phd-clone-b9b86fc4-0d20-4d90-ab09-31e5985c32f7\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1582026-05-08T11:26:57.878Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.862234155Z","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-08T11:26:57.878Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.862302938Z","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 }","guest_os_kind":"Alpine","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1602026-05-08T11:26:57.878Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.862358947Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/4477358be20ac71d760235f408dc63803d706c27d771ddc1eff467c60d6fb18d/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1612026-05-08T11:26:57.878Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:26:57.862443473Z","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/2a49b9cfb8d4793fd99b286657792aa19f0f70c5/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1622026-05-08T11:27:07.828Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:07.816028106Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/4477358be20ac71d760235f408dc63803d706c27d771ddc1eff467c60d6fb18d/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632026-05-08T11:27:07.828Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:07.816117024Z","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-08T11:27:27.293Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.281047604Z","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/4477358be20ac71d760235f408dc63803d706c27d771ddc1eff467c60d6fb18d/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-05-08T11:27:27.318Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.281625779Z","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-08T11:27:27.395Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 833","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.384024688Z","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-08T11:27:27.420Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.39786956Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1682026-05-08T11:27:27.420Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.405333866Z","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)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1692026-05-08T11:27:27.420Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.406460067Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":29541,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1702026-05-08T11:27:27.930Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.918889333Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-05-08T11:27:27.977Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.922598804Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 41bd7ab2-7961-44f6-bf96-90f6f42a5a44, name: \"phd-vm-41bd7ab2-7961-44f6-bf96-90f6f42a5a44\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 3440b65d-8c5a-4347-b92a-b9e25e787718, project_id: ba1080e4-a11e-4cff-8295-09f471d0c884, sled_id: 6c38396b-a7e7-4fb4-abb7-39209735c041, sled_serial: \"6c38396b-a7e7-4fb4-abb7-39209735c041\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1722026-05-08T11:27:27.977Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.923137474Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1732026-05-08T11:27:27.977Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.923197277Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1742026-05-08T11:27:27.977Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.925372464Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":2,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1752026-05-08T11:27:27.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.925954217Z","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-08T11:27:27.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.926048041Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1772026-05-08T11:27:27.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.926110259Z","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-08T11:27:27.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.926166418Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1792026-05-08T11:27:27.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:27.926216285Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1802026-05-08T11:27:32.562Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.550641468Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4624,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1812026-05-08T11:27:32.562Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.550731298Z","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-08T11:27:32.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.55223792Z","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-08T11:27:32.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.552292944Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1842026-05-08T11:27:32.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.552334442Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1852026-05-08T11:27:32.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.569035631Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":16,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1862026-05-08T11:27:32.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.569176698Z","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-08T11:27:32.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.569423836Z","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-08T11:27:32.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.569495441Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1892026-05-08T11:27:32.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.569553381Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1902026-05-08T11:27:32.613Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.601527424Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1912026-05-08T11:27:32.613Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.601640659Z","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-08T11:27:32.638Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.601742932Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4675,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1932026-05-08T11:27:32.638Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.60198494Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1942026-05-08T11:27:32.638Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.602141336Z","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)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1952026-05-08T11:27:32.638Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.612911399Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1962026-05-08T11:27:32.638Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.613196919Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1972026-05-08T11:27:32.638Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.613285647Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
1982026-05-08T11:27:32.662Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.645979002Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1992026-05-08T11:27:32.663Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.646223124Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2002026-05-08T11:27:32.663Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.646318144Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2012026-05-08T11:27:32.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.656718888Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2022026-05-08T11:27:32.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.65695235Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2032026-05-08T11:27:32.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.657047059Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2042026-05-08T11:27:32.712Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.689843279Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2052026-05-08T11:27:32.712Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.690033789Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2062026-05-08T11:27:32.712Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.690090787Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2072026-05-08T11:27:32.737Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.700403133Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2082026-05-08T11:27:32.737Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.700646133Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2092026-05-08T11:27:32.737Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.700764998Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2102026-05-08T11:27:32.761Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.733553974Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2112026-05-08T11:27:32.761Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.733852169Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2122026-05-08T11:27:32.761Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.733955975Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2132026-05-08T11:27:32.762Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.744432023Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2142026-05-08T11:27:32.762Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.744683589Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2152026-05-08T11:27:32.762Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.744782887Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2162026-05-08T11:27:32.789Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.777741236Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2172026-05-08T11:27:32.814Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.77796794Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2182026-05-08T11:27:32.814Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.778128295Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2192026-05-08T11:27:32.814Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.788627206Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2202026-05-08T11:27:32.814Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.788857442Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2212026-05-08T11:27:32.814Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.788952912Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2222026-05-08T11:27:32.839Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.821928752Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2232026-05-08T11:27:32.839Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.822181961Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2242026-05-08T11:27:32.839Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.822288333Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2252026-05-08T11:27:32.863Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.832902981Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2262026-05-08T11:27:32.864Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.833136002Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2272026-05-08T11:27:32.864Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.833242434Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2282026-05-08T11:27:32.888Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.865575276Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2292026-05-08T11:27:32.888Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.866191523Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2302026-05-08T11:27:32.888Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.866270372Z","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-08T11:27:32.888Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.86631691Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2322026-05-08T11:27:32.888Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.866726134Z","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-08T11:27:32.888Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.866783653Z","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-08T11:27:32.888Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.866832656Z","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:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2352026-05-08T11:27:32.889Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.86689298Z","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-08T11:27:32.913Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 834","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.898467448Z","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-08T11:27:32.937Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.911603328Z","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-08T11:27:32.937Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.911686686Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2392026-05-08T11:27:32.937Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.911754705Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"467d96b8-05ec-4d62-92a4-c8c31da2e0e3","source_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2402026-05-08T11:27:32.937Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.911812544Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","vm":"migration_from_base_lifecycle_0"}
2412026-05-08T11:27:32.937Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:32.912339832Z","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_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","vm":"migration_from_base_lifecycle_0"}
2422026-05-08T11:27:33.712Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:33.700023118Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: cf1fc084-5fa6-4ad6-8765-b4224ed6b039, name: \"phd-vm-cf1fc084-5fa6-4ad6-8765-b4224ed6b039\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 3440b65d-8c5a-4347-b92a-b9e25e787718, project_id: ba1080e4-a11e-4cff-8295-09f471d0c884, sled_id: ef0b26d6-54a0-403f-9f12-326d605222ed, sled_serial: \"ef0b26d6-54a0-403f-9f12-326d605222ed\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","vm":"migration_from_base_lifecycle_0"}
2432026-05-08T11:27:33.712Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:33.700229058Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","migration_id":"467d96b8-05ec-4d62-92a4-c8c31da2e0e3"}
2442026-05-08T11:27:36.407Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.395140081Z","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-08T11:27:36.607Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.595080957Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2462026-05-08T11:27:36.607Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.595161229Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":2894,"target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","migration_id":"467d96b8-05ec-4d62-92a4-c8c31da2e0e3"}
2472026-05-08T11:27:36.631Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.598576493Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2482026-05-08T11:27:36.631Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.599961971Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2492026-05-08T11:27:36.631Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.600015837Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2502026-05-08T11:27:36.631Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.603147783Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44"}
2512026-05-08T11:27:36.701Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.690203765Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":88,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2522026-05-08T11:27:36.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.690467815Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":90,"vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2532026-05-08T11:27:36.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.690739649Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2542026-05-08T11:27:36.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.690836703Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2552026-05-08T11:27:36.726Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.691921696Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9293,"vm_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2562026-05-08T11:27:36.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.723903194Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2572026-05-08T11:27:36.751Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.724060442Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2582026-05-08T11:27:36.751Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.724339881Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2592026-05-08T11:27:36.751Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.72446627Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8804}
2602026-05-08T11:27:36.751Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.724514752Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2612026-05-08T11:27:36.751Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.724666739Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2622026-05-08T11:27:36.751Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:36.72607475Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2632026-05-08T11:27:37.292Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.280832355Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2642026-05-08T11:27:37.374Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.362495662Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2652026-05-08T11:27:37.374Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.36258952Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-b9b86fc4-0d20-4d90-ab09-31e5985c32f7\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2662026-05-08T11:27:37.400Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.388552488Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2672026-05-08T11:27:37.400Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.388611069Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-858b10e8-f48f-407c-b75a-a4fbe7c52a76\"]","verb":"destroy","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039"}
2682026-05-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.406915371Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":682,"vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2692026-05-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407231009Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":682}
2702026-05-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407343092Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2712026-05-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407255966Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4495,"target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","source":"migration_from_base","source_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","vm_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2722026-05-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407421701Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2732026-05-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407425843Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"41bd7ab2-7961-44f6-bf96-90f6f42a5a44","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":4495,"target_id":"cf1fc084-5fa6-4ad6-8765-b4224ed6b039","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2742026-05-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.40748529Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2752026-05-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407520475Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":47032,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2762026-05-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407642956Z","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-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407755266Z","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-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407839491Z","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-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407908284Z","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-08T11:27:37.425Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.407985173Z","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::serial_history"}
2812026-05-08T11:27:37.450Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.422590278Z","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-08T11:27:37.450Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.422788052Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-a6f769fd-fc2f-4b6d-b518-6f8f8f4f681d\"]","path":"phd_tests::migrate::from_base::serial_history"}
2832026-05-08T11:27:37.475Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.439396513Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-a6f769fd-fc2f-4b6d-b518-6f8f8f4f681d\", \"phd-artifacts/phd-clone-3d384c9d-ef66-44a1-b0a8-92ec9482dbd2\"]","path":"phd_tests::migrate::from_base::serial_history"}
2842026-05-08T11:27:37.475Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.455519577Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-3d384c9d-ef66-44a1-b0a8-92ec9482dbd2\"]","path":"phd_tests::migrate::from_base::serial_history"}
2852026-05-08T11:27:37.499Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.466904536Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-3d384c9d-ef66-44a1-b0a8-92ec9482dbd2 0B 25.3T 1024M /phd-artifacts/phd-clone-3d384c9d-ef66-44a1-b0a8-92ec9482dbd2\n","path":"phd_tests::migrate::from_base::serial_history"}
2862026-05-08T11:27:37.499Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.467534438Z","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-08T11:27:37.499Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.467629297Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
2882026-05-08T11:27:37.500Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.467702366Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/4477358be20ac71d760235f408dc63803d706c27d771ddc1eff467c60d6fb18d/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2892026-05-08T11:27:37.500Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.467758943Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/4477358be20ac71d760235f408dc63803d706c27d771ddc1eff467c60d6fb18d/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
2902026-05-08T11:27:37.500Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.467828705Z","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::serial_history/migration_serial_history_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2912026-05-08T11:27:37.525Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 843","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.499826143Z","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-08T11:27:37.549Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.514116418Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":46}
2932026-05-08T11:27:37.550Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.514217199Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
2942026-05-08T11:27:37.550Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:37.51491549Z","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)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
2952026-05-08T11:27:38.084Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.072885425Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2962026-05-08T11:27:38.131Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.073639366Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 51aeb8ca-ae68-4084-b56b-2bb085ba23eb, name: \"phd-vm-51aeb8ca-ae68-4084-b56b-2bb085ba23eb\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 8f46fbcd-b578-42c9-b02d-64bec75f8558, project_id: c2612c86-ad3f-436d-83ea-8e00a2ccb7c7, sled_id: dd9a5bca-a56c-41ca-8f69-20ea56d0214b, sled_serial: \"dd9a5bca-a56c-41ca-8f69-20ea56d0214b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
2972026-05-08T11:27:38.131Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.073779525Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
2982026-05-08T11:27:38.131Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.073831101Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
2992026-05-08T11:27:38.131Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.074707953Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3002026-05-08T11:27:38.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.074785971Z","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-08T11:27:38.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.074840003Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3022026-05-08T11:27:38.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.074884157Z","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-08T11:27:38.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.074924874Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3042026-05-08T11:27:38.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:38.074972123Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3052026-05-08T11:27:42.636Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.624019379Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4548,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3062026-05-08T11:27:42.636Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.624102485Z","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-08T11:27:42.636Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.6242687Z","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-08T11:27:42.636Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.6243179Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3092026-05-08T11:27:42.636Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.624359096Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3102026-05-08T11:27:42.661Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.642692069Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3112026-05-08T11:27:42.661Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.642799532Z","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-08T11:27:42.661Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.643024027Z","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-08T11:27:42.661Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.643069232Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3142026-05-08T11:27:42.661Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.643104329Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3152026-05-08T11:27:42.686Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.674970931Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3162026-05-08T11:27:42.686Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.675131285Z","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-08T11:27:42.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.67520669Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4600}
3182026-05-08T11:27:42.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.675467002Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3192026-05-08T11:27:42.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.675582317Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3202026-05-08T11:27:42.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.685991137Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3212026-05-08T11:27:42.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.686224268Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3222026-05-08T11:27:42.711Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.68632006Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3232026-05-08T11:27:42.735Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.718833484Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3242026-05-08T11:27:42.735Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.719080001Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3252026-05-08T11:27:42.735Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.719151125Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3262026-05-08T11:27:42.760Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.730402419Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3272026-05-08T11:27:42.760Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.730628968Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3282026-05-08T11:27:42.760Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.73072529Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3292026-05-08T11:27:42.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.763240458Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3302026-05-08T11:27:42.785Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.768107329Z","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-08T11:27:42.785Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.768196438Z","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-08T11:27:42.785Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.768240471Z","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-08T11:27:42.785Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.768299323Z","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-08T11:27:42.785Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.768345821Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
3352026-05-08T11:27:42.785Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.768418067Z","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::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
3362026-05-08T11:27:42.810Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 844","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.799303931Z","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-08T11:27:42.835Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.812090387Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":43}
3382026-05-08T11:27:42.835Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.812166131Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3392026-05-08T11:27:42.835Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.812222563Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"0905aec0-8d07-42a0-a3c9-da33c7ad901e","timeout_duration":"45s","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3402026-05-08T11:27:42.835Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.812272231Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3412026-05-08T11:27:42.835Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:42.812861039Z","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":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3422026-05-08T11:27:43.310Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:43.298522217Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0, name: \"phd-vm-1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 8f46fbcd-b578-42c9-b02d-64bec75f8558, project_id: c2612c86-ad3f-436d-83ea-8e00a2ccb7c7, sled_id: 903ce841-5db6-4d69-8910-fd505b91dcfb, sled_serial: \"903ce841-5db6-4d69-8910-fd505b91dcfb\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3432026-05-08T11:27:43.310Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:43.298709472Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"0905aec0-8d07-42a0-a3c9-da33c7ad901e","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3442026-05-08T11:27:46.075Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:46.063633636Z","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-08T11:27:46.919Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:46.907511833Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3462026-05-08T11:27:46.919Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:46.907589841Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"0905aec0-8d07-42a0-a3c9-da33c7ad901e","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","elapsed_milliseconds":3608,"path":"phd_tests::migrate::from_base::serial_history","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3472026-05-08T11:27:46.944Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:46.909491734Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3482026-05-08T11:27:46.944Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:46.911335128Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb"}
3492026-05-08T11:27:47.009Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:46.998019386Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":88,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3502026-05-08T11:27:47.034Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:46.998243991Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9483,"vm":"migration_serial_history_base","vm_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","path":"phd_tests::migrate::from_base::serial_history"}
3512026-05-08T11:27:47.034Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.000913554Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3522026-05-08T11:27:47.034Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.001124493Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3532026-05-08T11:27:47.034Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.001279306Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8927}
3542026-05-08T11:27:47.034Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.001341944Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3552026-05-08T11:27:47.034Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.00148241Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3562026-05-08T11:27:47.034Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.002544691Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3572026-05-08T11:27:47.311Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.299304236Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3582026-05-08T11:27:47.385Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.373331929Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3592026-05-08T11:27:47.385Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.37339602Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-3d384c9d-ef66-44a1-b0a8-92ec9482dbd2\"]","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3602026-05-08T11:27:47.410Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.397782585Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3612026-05-08T11:27:47.410Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.397839382Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-a6f769fd-fc2f-4b6d-b518-6f8f8f4f681d\"]","verb":"destroy","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3622026-05-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.415319545Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":413,"vm":"migration_serial_history_base_lifecycle_0","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0","path":"phd_tests::migrate::from_base::serial_history"}
3632026-05-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.415703392Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":414}
3642026-05-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.415733038Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4603}
3652026-05-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.415812899Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3662026-05-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.415857954Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3672026-05-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.415849729Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"51aeb8ca-ae68-4084-b56b-2bb085ba23eb","elapsed_milliseconds":4603,"path":"phd_tests::migrate::from_base::serial_history","target_id":"1bb4a3c6-6d2d-493c-a6a2-0226c0dadda0"}
3682026-05-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.415901396Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3692026-05-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.415926704Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":10007}
3702026-05-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.416103509Z","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-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.416226191Z","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-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.416292326Z","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-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.416348673Z","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-08T11:27:47.435Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.416419627Z","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-08T11:27:47.460Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.428665223Z","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-08T11:27:47.460Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.428794117Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-012c825b-0687-4bfe-a757-fb4f6bc90004\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-05-08T11:27:47.460Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.44494306Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-012c825b-0687-4bfe-a757-fb4f6bc90004\", \"phd-artifacts/phd-clone-2917d9a3-7909-4694-ac9d-149361ef0542\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-05-08T11:27:47.485Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.461636484Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-2917d9a3-7909-4694-ac9d-149361ef0542\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-05-08T11:27:47.485Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.47331106Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-2917d9a3-7909-4694-ac9d-149361ef0542 0B 25.3T 1024M /phd-artifacts/phd-clone-2917d9a3-7909-4694-ac9d-149361ef0542\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-05-08T11:27:47.509Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.473907319Z","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-08T11:27:47.509Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.473970636Z","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 }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-05-08T11:27:47.509Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.474029312Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/4477358be20ac71d760235f408dc63803d706c27d771ddc1eff467c60d6fb18d/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-05-08T11:27:47.509Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.474087782Z","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/4477358be20ac71d760235f408dc63803d706c27d771ddc1eff467c60d6fb18d/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-05-08T11:27:47.509Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.474161994Z","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.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-05-08T11:27:47.534Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 853","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.509221853Z","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-08T11:27:47.558Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.52319512Z","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":49}
3872026-05-08T11:27:47.558Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.523309547Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
3882026-05-08T11:27:47.558Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.52398776Z","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)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
3892026-05-08T11:27:47.910Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.898992862Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3902026-05-08T11:27:47.935Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.900292632Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: bf9dda78-c044-48bd-b673-45a018fe2272, name: \"phd-vm-bf9dda78-c044-48bd-b673-45a018fe2272\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 51371c29-c1f7-4002-b70b-f260fb927d24, project_id: 040a8ff8-7ad7-42d2-92fd-bb34f963c720, sled_id: 1796e2bc-5c57-4cc2-9a5d-948c8afa5a0b, sled_serial: \"1796e2bc-5c57-4cc2-9a5d-948c8afa5a0b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
3912026-05-08T11:27:47.935Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.900475939Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
3922026-05-08T11:27:47.935Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.900530773Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
3932026-05-08T11:27:47.935Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.90164947Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":1}
3942026-05-08T11:27:47.936Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.901732217Z","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-08T11:27:47.936Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.901789906Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-05-08T11:27:47.936Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.901836414Z","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-08T11:27:47.936Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.901878193Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
3982026-05-08T11:27:47.936Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:47.90192398Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
3992026-05-08T11:27:52.441Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.429349508Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4527}
4002026-05-08T11:27:52.441Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.429443155Z","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-08T11:27:52.441Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.429696735Z","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-08T11:27:52.441Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.429769222Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4032026-05-08T11:27:52.441Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.429819798Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4042026-05-08T11:27:52.466Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.447316813Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":17}
4052026-05-08T11:27:52.466Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.447462969Z","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-08T11:27:52.466Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.447921677Z","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-08T11:27:52.466Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.448036946Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4082026-05-08T11:27:52.467Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.448122518Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4092026-05-08T11:27:52.491Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.479907522Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":31}
4102026-05-08T11:27:52.491Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.480022546Z","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-08T11:27:52.492Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.480093734Z","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":4578}
4122026-05-08T11:27:52.516Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.480316207Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4132026-05-08T11:27:52.516Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.480365781Z","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","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4142026-05-08T11:27:52.516Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.490803346Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4152026-05-08T11:27:52.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.491045144Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4162026-05-08T11:27:52.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.491144421Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4172026-05-08T11:27:52.542Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.523922427Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4182026-05-08T11:27:52.542Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.524228245Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4192026-05-08T11:27:52.542Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.524338564Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4202026-05-08T11:27:52.566Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.53469311Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4212026-05-08T11:27:52.566Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.534935569Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4222026-05-08T11:27:52.566Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.535035118Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4232026-05-08T11:27:52.591Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.567929694Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4242026-05-08T11:27:52.591Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.56817593Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4252026-05-08T11:27:52.591Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.568272462Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4262026-05-08T11:27:52.591Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.578807813Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4272026-05-08T11:27:52.591Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.579046164Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4282026-05-08T11:27:52.591Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.579142636Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4292026-05-08T11:27:52.623Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.612090493Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4302026-05-08T11:27:52.648Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.612334114Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4312026-05-08T11:27:52.648Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.612435656Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4322026-05-08T11:27:52.648Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.623046418Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4332026-05-08T11:27:52.648Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.623295589Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4342026-05-08T11:27:52.648Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.623395418Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4352026-05-08T11:27:52.673Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.656255719Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4362026-05-08T11:27:52.673Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.656497076Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4372026-05-08T11:27:52.673Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.656597246Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4382026-05-08T11:27:52.698Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.667303134Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4392026-05-08T11:27:52.698Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.667561943Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4402026-05-08T11:27:52.698Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.667647906Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4412026-05-08T11:27:52.723Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.700647796Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4422026-05-08T11:27:52.723Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.700905214Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4432026-05-08T11:27:52.723Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.700998831Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4442026-05-08T11:27:52.723Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.711431274Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4452026-05-08T11:27:52.723Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.711659466Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4462026-05-08T11:27:52.723Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.711736813Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4472026-05-08T11:27:52.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.744416131Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4482026-05-08T11:27:52.756Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.744543362Z","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"}
4492026-05-08T11:27:52.781Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.74466405Z","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-08T11:27:52.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.744744893Z","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 }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-05-08T11:27:52.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.74482758Z","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-08T11:27:52.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.744873016Z","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-08T11:27:52.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.744939822Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-05-08T11:27:52.806Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 854","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.776428367Z","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-08T11:27:52.806Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.789398874Z","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":44}
4562026-05-08T11:27:52.806Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.789478535Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","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":"bf9dda78-c044-48bd-b673-45a018fe2272"}
4572026-05-08T11:27:52.806Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.789542997Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"97c1dd0e-17ce-4444-ab9d-2e2e421fd13a","timeout_duration":"45s","target_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","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":"bf9dda78-c044-48bd-b673-45a018fe2272"}
4582026-05-08T11:27:52.806Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.789605606Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","target":"migration_from_base_and_back_lifecycle_0","vm":"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":"bf9dda78-c044-48bd-b673-45a018fe2272"}
4592026-05-08T11:27:52.806Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:52.790143133Z","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":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","target":"migration_from_base_and_back_lifecycle_0","vm":"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":"bf9dda78-c044-48bd-b673-45a018fe2272"}
4602026-05-08T11:27:53.417Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:53.404925917Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 9868128a-7d02-4466-9dec-58e9ac85ec00, name: \"phd-vm-9868128a-7d02-4466-9dec-58e9ac85ec00\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 51371c29-c1f7-4002-b70b-f260fb927d24, project_id: 040a8ff8-7ad7-42d2-92fd-bb34f963c720, sled_id: 12e4e4d2-aa1d-457e-ba95-d6833653730a, sled_serial: \"12e4e4d2-aa1d-457e-ba95-d6833653730a\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","target":"migration_from_base_and_back_lifecycle_0","vm":"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":"bf9dda78-c044-48bd-b673-45a018fe2272"}
4612026-05-08T11:27:53.417Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:53.405120384Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","target":"migration_from_base_and_back_lifecycle_0","migration_id":"97c1dd0e-17ce-4444-ab9d-2e2e421fd13a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"bf9dda78-c044-48bd-b673-45a018fe2272"}
4622026-05-08T11:27:56.148Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:56.137019785Z","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-08T11:27:58.281Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.269998645Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","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":"bf9dda78-c044-48bd-b673-45a018fe2272"}
4642026-05-08T11:27:58.281Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.270076582Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","target":"migration_from_base_and_back_lifecycle_0","migration_id":"97c1dd0e-17ce-4444-ab9d-2e2e421fd13a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"bf9dda78-c044-48bd-b673-45a018fe2272","elapsed_milliseconds":4864}
4652026-05-08T11:27:58.306Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.272695223Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4662026-05-08T11:27:58.306Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.272940637Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm":"migration_from_base_and_back_lifecycle_0"}
4672026-05-08T11:27:58.306Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.273001746Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm":"migration_from_base_and_back_lifecycle_0"}
4682026-05-08T11:27:58.306Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.274925718Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back"}
4692026-05-08T11:27:58.372Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.36083546Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":87}
4702026-05-08T11:27:58.397Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.361054054Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":88}
4712026-05-08T11:27:58.397Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.361082568Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bf9dda78-c044-48bd-b673-45a018fe2272","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10837}
4722026-05-08T11:27:58.397Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.361293878Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm":"migration_from_base_and_back_lifecycle_0"}
4732026-05-08T11:27:58.397Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.361371675Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm":"migration_from_base_and_back_lifecycle_0"}
4742026-05-08T11:27:58.422Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.39428691Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4752026-05-08T11:27:58.422Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.394438667Z","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-08T11:27:58.422Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.394569966Z","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-08T11:27:58.422Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.394652372Z","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_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-05-08T11:27:58.422Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.394763132Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/4477358be20ac71d760235f408dc63803d706c27d771ddc1eff467c60d6fb18d/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-05-08T11:27:58.422Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.394858552Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9004","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/4477358be20ac71d760235f408dc63803d706c27d771ddc1eff467c60d6fb18d/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-05-08T11:27:58.422Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.394927473Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-05-08T11:27:58.447Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 856","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.42808685Z","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-08T11:27:58.472Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.442179583Z","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":47}
4832026-05-08T11:27:58.472Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.44227302Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","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":"9868128a-7d02-4466-9dec-58e9ac85ec00"}
4842026-05-08T11:27:58.472Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.442350136Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"f67fcd0e-3c77-4c6e-a3ec-4c39593fc9ae","timeout_duration":"45s","target_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","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":"9868128a-7d02-4466-9dec-58e9ac85ec00"}
4852026-05-08T11:27:58.472Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.44242622Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","target":"migration_from_base_and_back_lifecycle_1","vm":"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":"9868128a-7d02-4466-9dec-58e9ac85ec00"}
4862026-05-08T11:27:58.472Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:58.443013081Z","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":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","target":"migration_from_base_and_back_lifecycle_1","vm":"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":"9868128a-7d02-4466-9dec-58e9ac85ec00"}
4872026-05-08T11:27:59.073Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:59.061743343Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: d2cbcdaf-3bdd-4424-888e-eca17c31c0f6, name: \"phd-vm-d2cbcdaf-3bdd-4424-888e-eca17c31c0f6\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 51371c29-c1f7-4002-b70b-f260fb927d24, project_id: 040a8ff8-7ad7-42d2-92fd-bb34f963c720, sled_id: a29378e3-03fe-46a2-892a-a80e585a1328, sled_serial: \"a29378e3-03fe-46a2-892a-a80e585a1328\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","target":"migration_from_base_and_back_lifecycle_1","vm":"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":"9868128a-7d02-4466-9dec-58e9ac85ec00"}
4882026-05-08T11:27:59.073Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:27:59.061944624Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","target":"migration_from_base_and_back_lifecycle_1","migration_id":"f67fcd0e-3c77-4c6e-a3ec-4c39593fc9ae","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"9868128a-7d02-4466-9dec-58e9ac85ec00"}
4892026-05-08T11:28:01.751Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:01.739525212Z","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-08T11:28:02.884Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.872484992Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","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":"9868128a-7d02-4466-9dec-58e9ac85ec00"}
4912026-05-08T11:28:02.884Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.872564502Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","target":"migration_from_base_and_back_lifecycle_1","migration_id":"f67fcd0e-3c77-4c6e-a3ec-4c39593fc9ae","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","elapsed_milliseconds":3810}
4922026-05-08T11:28:02.909Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.874874845Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm":"migration_from_base_and_back_lifecycle_0"}
4932026-05-08T11:28:02.909Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.875106073Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm":"migration_from_base_and_back_lifecycle_1"}
4942026-05-08T11:28:02.909Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.875158913Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm":"migration_from_base_and_back_lifecycle_1"}
4952026-05-08T11:28:02.909Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.876649374Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm":"migration_from_base_and_back_lifecycle_0"}
4962026-05-08T11:28:02.967Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.955915381Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":80}
4972026-05-08T11:28:02.992Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.956169893Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":81}
4982026-05-08T11:28:02.992Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.956177347Z","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":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"bf9dda78-c044-48bd-b673-45a018fe2272","elapsed_milliseconds":10165,"target_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","vm_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","source":"migration_from_base_and_back"}
4992026-05-08T11:28:02.992Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.956329325Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm":"migration_from_base_and_back_lifecycle_1"}
5002026-05-08T11:28:02.992Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.956328353Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","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":"bf9dda78-c044-48bd-b673-45a018fe2272","elapsed_milliseconds":10166}
5012026-05-08T11:28:02.992Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.956386924Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm":"migration_from_base_and_back_lifecycle_1"}
5022026-05-08T11:28:03.017Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.986938024Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":30}
5032026-05-08T11:28:03.017Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.98711544Z","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-08T11:28:03.017Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.987251588Z","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-08T11:28:03.017Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.987335677Z","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_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-05-08T11:28:03.017Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.987444152Z","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-08T11:28:03.017Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.987533311Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9006","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-05-08T11:28:03.017Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:02.987645654Z","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-08T11:28:03.042Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 858","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:03.020995986Z","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-08T11:28:03.067Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:03.035495876Z","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-08T11:28:03.067Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:03.035574144Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","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":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6"}
5122026-05-08T11:28:03.067Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:03.035636713Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"95269005-2de7-47b6-a7fd-c4fdf83d400d","target_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","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":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6"}
5132026-05-08T11:28:03.067Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:03.035693711Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","target":"migration_from_base_and_back_lifecycle_2","vm":"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":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6"}
5142026-05-08T11:28:03.067Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:03.036277285Z","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":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","target":"migration_from_base_and_back_lifecycle_2","vm":"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":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6"}
5152026-05-08T11:28:03.903Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:03.891411765Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 33a0ef13-e3a8-40d0-9a25-9093c106be5a, name: \"phd-vm-33a0ef13-e3a8-40d0-9a25-9093c106be5a\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 51371c29-c1f7-4002-b70b-f260fb927d24, project_id: 040a8ff8-7ad7-42d2-92fd-bb34f963c720, sled_id: 712c94f0-a559-4845-8169-9bea9436eb3a, sled_serial: \"712c94f0-a559-4845-8169-9bea9436eb3a\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","target":"migration_from_base_and_back_lifecycle_2","vm":"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":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6"}
5162026-05-08T11:28:03.903Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:03.891592978Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","target":"migration_from_base_and_back_lifecycle_2","migration_id":"95269005-2de7-47b6-a7fd-c4fdf83d400d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6"}
5172026-05-08T11:28:06.648Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:06.637306431Z","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-08T11:28:08.312Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.300321758Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","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":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6"}
5192026-05-08T11:28:08.312Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.300400704Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","target":"migration_from_base_and_back_lifecycle_2","migration_id":"95269005-2de7-47b6-a7fd-c4fdf83d400d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","elapsed_milliseconds":4408}
5202026-05-08T11:28:08.336Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.302546762Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm":"migration_from_base_and_back_lifecycle_1"}
5212026-05-08T11:28:08.337Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.302757972Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5222026-05-08T11:28:08.337Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.302817344Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5232026-05-08T11:28:08.337Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.304412063Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm":"migration_from_base_and_back_lifecycle_1"}
5242026-05-08T11:28:08.402Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.391255763Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":88}
5252026-05-08T11:28:08.427Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.391552494Z","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":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9868128a-7d02-4466-9dec-58e9ac85ec00","elapsed_milliseconds":9948,"target_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","vm_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","source":"migration_from_base_and_back_lifecycle_0"}
5262026-05-08T11:28:08.427Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.39161882Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":88}
5272026-05-08T11:28:08.427Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.391694353Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","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":"9868128a-7d02-4466-9dec-58e9ac85ec00","elapsed_milliseconds":9948}
5282026-05-08T11:28:08.428Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.391817796Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5292026-05-08T11:28:08.428Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.391895854Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5302026-05-08T11:28:08.453Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.425171371Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":33}
5312026-05-08T11:28:08.453Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.425351873Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5322026-05-08T11:28:08.453Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.425573733Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5332026-05-08T11:28:08.453Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.425697276Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":20525}
5342026-05-08T11:28:08.453Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.425744506Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5352026-05-08T11:28:08.453Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.425875303Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5362026-05-08T11:28:08.453Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.427956693Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5372026-05-08T11:28:08.899Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.887843761Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5382026-05-08T11:28:08.978Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.966830783Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5392026-05-08T11:28:08.978Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.966941673Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-2917d9a3-7909-4694-ac9d-149361ef0542\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5402026-05-08T11:28:09.010Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.998540185Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5412026-05-08T11:28:09.035Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:08.998605198Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-012c825b-0687-4bfe-a757-fb4f6bc90004\"]","verb":"destroy","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2"}
5422026-05-08T11:28:09.035Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:09.016212161Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":590}
5432026-05-08T11:28:09.035Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:09.016474007Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":590}
5442026-05-08T11:28:09.035Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:09.016462174Z","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":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","elapsed_milliseconds":5980,"target_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","vm_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","source":"migration_from_base_and_back_lifecycle_1"}
5452026-05-08T11:28:09.035Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:09.016560961Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"33a0ef13-e3a8-40d0-9a25-9093c106be5a","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":"d2cbcdaf-3bdd-4424-888e-eca17c31c0f6","elapsed_milliseconds":5980}
5462026-05-08T11:28:09.035Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:09.016590006Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5472026-05-08T11:28:09.035Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:09.016615154Z","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":21599}
5482026-05-08T11:28:09.035Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:09.016631194Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5492026-05-08T11:28:09.035Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 78.64s
5502026-05-08T11:28:09.035Z
5512026-05-08T11:28:09.035Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220060","pid":828,"time":"2026-05-08T11:28:09.018600241Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5522026-05-08T11:28:09.140Z
5532026-05-08T11:28:09.140Zreal 1:19.752734641
5542026-05-08T11:28:09.140Zuser 44.686933078
5552026-05-08T11:28:09.140Zsys 20.245717841
5562026-05-08T11:28:09.165Ztrap 0.006943948
5572026-05-08T11:28:09.165Ztflt 0.003159110
5582026-05-08T11:28:09.165Zdflt 0.003443231
5592026-05-08T11:28:09.165Zkflt 0.000000000
5602026-05-08T11:28:09.165Zlock 3:09:13.580987040
5612026-05-08T11:28:09.165Zslp 4:08.169321628
5622026-05-08T11:28:09.165Zlat 1.664705626
5632026-05-08T11:28:09.165Zstop 33.805865548
5642026-05-08T11:28:09.165Z+ failcount=0
5652026-05-08T11:28:09.165Z+ set -e
5662026-05-08T11:28:09.165Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5672026-05-08T11:28:09.165ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5682026-05-08T11:28:09.165Za ./ 0K
5692026-05-08T11:28:09.165Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5702026-05-08T11:28:09.165Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 138K
5712026-05-08T11:28:09.165Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5722026-05-08T11:28:09.165Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5732026-05-08T11:28:09.165Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 143K
5742026-05-08T11:28:09.165Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5752026-05-08T11:28:09.165Za ./phd_tests::migrate::from_base::serial_history/ 0K
5762026-05-08T11:28:09.165Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 138K
5772026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5782026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5792026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 144K
5802026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5812026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5822026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 138K
5832026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5842026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5852026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 231K
5862026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5872026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 231K
5882026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5892026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 144K
5902026-05-08T11:28:09.166Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5912026-05-08T11:28:09.191Z+ exitcode=0
5922026-05-08T11:28:09.191Z+ '[' 0 -eq 0 ']'
5932026-05-08T11:28:09.191Z+ echo
5942026-05-08T11:28:09.191Z
5952026-05-08T11:28:09.191Z+ echo 'ALL TESTS PASSED'
5962026-05-08T11:28:09.191ZALL TESTS PASSED
5972026-05-08T11:28:09.191Z
5982026-05-08T11:28:09.191Z+ echo
5992026-05-08T11:28:09.191Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6002026-05-08T11:28:09.191Z+ read
6012026-05-08T11:28:09.191Z+ exit 0
6022026-05-08T11:28:09.191Zprocess exited: duration 120669 ms, exit code 0
 
6032026-05-08T11:28:09.243Zfound 2 output files
6042026-05-08T11:28:09.271Zuploading: /tmp/phd-runner.log (184416 bytes)
6052026-05-08T11:28:10.391Zuploaded: /tmp/phd-runner.log
6062026-05-08T11:28:10.415Zuploading: /tmp/phd-tmp-files.tar.gz (106404 bytes)
6072026-05-08T11:28:11.577Zuploaded: /tmp/phd-tmp-files.tar.gz