01KY3K5JW4JXD403TVYKC95ZYY: 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: 01KY3K5YFF5QA4B6F7HNSM7M28

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-07-22T00:32:36.348Zjob dependencies complete; ready to run (waiting for 11 m 3 s)
22026-07-22T00:36:03.814Zjob assigned to worker 01KY3KT7DSSQGD6Y0RGWYMBAR0 [factory edgar, gimlet/BRM42220060/929] (queued for 3 m 27 s)
32026-07-22T00:36:04.076Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-07-22T00:36:04.103Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-07-22T00:36:04.103Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-07-22T00:36:04.154Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-07-22T00:36:04.154Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-07-22T00:36:11.690Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-07-22T00:36:11.690Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-07-22T00:36:11.740Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-07-22T00:36:11.740Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-07-22T00:36:22.232Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-07-22T00:36:22.232Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-07-22T00:36:30.824Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-07-22T00:36:30.824Zstarting task 0: "setup"
162026-07-22T00:36:30.855Z++ uname -s
172026-07-22T00:36:30.855Z+ kern=SunOS
182026-07-22T00:36:30.855Z+ build_user=build
192026-07-22T00:36:30.855Z+ build_uid=12345
202026-07-22T00:36:30.855Z+ work_dir=/work
212026-07-22T00:36:30.855Z+ input_dir=/input
222026-07-22T00:36:30.855Z+ [[ 0 == 12345 ]]
232026-07-22T00:36:30.855Z+ case "$kern" in
242026-07-22T00:36:30.855Z+ groupadd -g 12345 build
252026-07-22T00:36:30.855Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-07-22T00:36:32.858Z+ zfs create -o mountpoint=/work rpool/work
272026-07-22T00:36:33.183Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-07-22T00:36:33.208Z+ home_fs=
292026-07-22T00:36:33.208Z+ [[ '' == autofs ]]
302026-07-22T00:36:33.208Z+ mkdir -p /home/build
312026-07-22T00:36:33.208Z+ chown build:build /home/build /work
322026-07-22T00:36:34.197Z+ chmod 0700 /home/build /work
332026-07-22T00:36:34.221Zprocess exited: duration 3377 ms, exit code 0
 
342026-07-22T00:36:34.269Zstarting task 1: "authentication"
352026-07-22T00:36:34.337Zprocess exited: duration 67 ms, exit code 0
 
362026-07-22T00:36:34.386Zstarting task 2: "build"
372026-07-22T00:36:34.412Z+ indir=/input
382026-07-22T00:36:34.412Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-07-22T00:36:34.412Z+ phddir=/work/phd-test
402026-07-22T00:36:34.412Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-07-22T00:36:34.436Z++ pilot local disk list -H -o type,disk
422026-07-22T00:36:34.436Z++ grep -v M.2
432026-07-22T00:36:34.436Z++ cut -f 2
442026-07-22T00:36:34.488Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC586d0 c9t0014EE81000BC57Cd0 c10t0014EE81000BC3CCd0 c11t0014EE81000BC478d0 c4t0014EE81000BC5BBd0 c3t0014EE81000BC247d0 c2t0014EE81000BC649d0 c6t0014EE81000BC634d0 c5t0014EE81000BC0B1d0
452026-07-22T00:36:37.045Z+ artifactdir=/phd-artifacts
462026-07-22T00:36:37.045Z+ banner Inputs
472026-07-22T00:36:37.069Z ###
482026-07-22T00:36:37.069Z # # # ##### # # ##### ####
492026-07-22T00:36:37.069Z # ## # # # # # # #
502026-07-22T00:36:37.069Z # # # # # # # # # ####
512026-07-22T00:36:37.069Z # # # # ##### # # # #
522026-07-22T00:36:37.069Z # # ## # # # # # #
532026-07-22T00:36:37.069Z ### # # # #### # ####
542026-07-22T00:36:37.069Z
552026-07-22T00:36:37.069Z+ find /input -ls
562026-07-22T00:36:37.069Z 34 1 drwxr-xr-x 3 root root 3 Jul 22 00:36 /input
572026-07-22T00:36:37.071Z 2 1 drwxr-xr-x 3 root root 3 Jul 22 00:36 /input/phd-build
582026-07-22T00:36:37.071Z 3 2 drwxr-xr-x 2 root root 8 Jul 22 00:36 /input/phd-build/out
592026-07-22T00:36:37.071Z 512 1 -rw-r--r-- 1 root root 65 Jul 22 00:36 /input/phd-build/out/propolis-server-debug.sha256.txt
602026-07-22T00:36:37.071Z 128 2 -rw-r--r-- 1 root root 2573 Jul 22 00:36 /input/phd-build/out/phd-run-with-args.sh
612026-07-22T00:36:37.072Z 384 161929 -rw-r--r-- 1 root root 165775443 Jul 22 00:36 /input/phd-build/out/phd-runner.tar.gz
622026-07-22T00:36:37.072Z 256 1 -rw-r--r-- 1 root root 65 Jul 22 00:36 /input/phd-build/out/phd-runner.sha256.txt
632026-07-22T00:36:37.072Z 768 183973 -rw-r--r-- 1 root root 188391871 Jul 22 00:36 /input/phd-build/out/propolis-tests-debug.tar.gz
642026-07-22T00:36:37.072Z 640 222200 -rw-r--r-- 1 root root 227580979 Jul 22 00:36 /input/phd-build/out/propolis-server-debug.tar.gz
652026-07-22T00:36:37.072Z+ rm -rf /work/phd-test
662026-07-22T00:36:37.072Z+ mkdir /work/phd-test
672026-07-22T00:36:37.072Z+ for p in $indir/$indir_suffix
682026-07-22T00:36:37.072Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-07-22T00:36:41.637ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-07-22T00:36:41.637Zx phd-runner, 606333832 bytes, 1184246 tape blocks
712026-07-22T00:36:41.637Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-07-22T00:36:41.661Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-07-22T00:36:45.606Z+ for f in $(tar tf "$p")
742026-07-22T00:36:45.607Z+ chmod +x /work/phd-test/phd-runner
752026-07-22T00:36:45.632Z+ for f in $(tar tf "$p")
762026-07-22T00:36:45.632Z+ chmod +x /work/phd-test/artifacts.toml
772026-07-22T00:36:45.632Z+ for p in $indir/$indir_suffix
782026-07-22T00:36:45.632Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-07-22T00:37:04.698ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-07-22T00:37:04.698Zx propolis-server, 871418680 bytes, 1701990 tape blocks
812026-07-22T00:37:04.723Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-07-22T00:37:09.994Z+ for f in $(tar tf "$p")
832026-07-22T00:37:09.994Z+ chmod +x /work/phd-test/propolis-server
842026-07-22T00:37:10.019Z+ for p in $indir/$indir_suffix
852026-07-22T00:37:10.019Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-07-22T00:37:26.006ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-07-22T00:37:26.006Zx target/debug/deps/propolis-a7ca583ea8a8cbd9, 721147816 bytes, 1408492 tape blocks
882026-07-22T00:37:26.031Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-07-22T00:37:30.478Z+ for f in $(tar tf "$p")
902026-07-22T00:37:30.478Z+ chmod +x /work/phd-test/target/debug/deps/propolis-a7ca583ea8a8cbd9
912026-07-22T00:37:30.502Z+ ls /work/phd-test
922026-07-22T00:37:30.502Zartifacts.toml
932026-07-22T00:37:30.502Zphd-runner
942026-07-22T00:37:30.502Zpropolis-server
952026-07-22T00:37:30.502Ztarget
962026-07-22T00:37:30.502Z+ banner Setup
972026-07-22T00:37:30.502Z #####
982026-07-22T00:37:30.502Z# # ###### ##### # # #####
992026-07-22T00:37:30.502Z# # # # # # #
1002026-07-22T00:37:30.502Z ##### ##### # # # # #
1012026-07-22T00:37:30.502Z # # # # # #####
1022026-07-22T00:37:30.502Z# # # # # # #
1032026-07-22T00:37:30.502Z ##### ###### # #### #
1042026-07-22T00:37:30.502Z
1052026-07-22T00:37:30.502Z+ tmpdir=/tmp/propolis-phd
1062026-07-22T00:37:30.502Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-07-22T00:37:30.502Z+ mkdir /tmp/propolis-phd
1082026-07-22T00:37:30.502Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-07-22T00:37:31.010Z+ banner Tests
1102026-07-22T00:37:31.034Z#######
1112026-07-22T00:37:31.035Z # ###### #### ##### ####
1122026-07-22T00:37:31.035Z # # # # #
1132026-07-22T00:37:31.035Z # ##### #### # ####
1142026-07-22T00:37:31.035Z # # # # #
1152026-07-22T00:37:31.035Z # # # # # # #
1162026-07-22T00:37:31.035Z # ###### #### # ####
1172026-07-22T00:37:31.035Z
1182026-07-22T00:37:31.035Z+ runner=/work/phd-test/phd-runner
1192026-07-22T00:37:31.035Z+ artifacts=/work/phd-test/artifacts.toml
1202026-07-22T00:37:31.036Z+ propolis=/work/phd-test/propolis-server
1212026-07-22T00:37:31.036Z+ ls /work/phd-test/phd-runner
1222026-07-22T00:37:31.036Z/work/phd-test/phd-runner
1232026-07-22T00:37:31.036Z+ ls /work/phd-test/artifacts.toml
1242026-07-22T00:37:31.036Z/work/phd-test/artifacts.toml
1252026-07-22T00:37:31.036Z+ ls /work/phd-test/propolis-server
1262026-07-22T00:37:31.036Z/work/phd-test/propolis-server
1272026-07-22T00:37:31.036Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-07-22T00:37:31.036Z+ set +e
1292026-07-22T00:37:31.036Z+ RUST_BACKTRACE=1
1302026-07-22T00:37:31.036Z+ RUST_LOG=info,phd=debug
1312026-07-22T00:37:31.036Z+ 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-07-22T00:37:31.036Z+ tee /tmp/phd-runner.log
1332026-07-22T00:37:31.255Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:31.235917538Z","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-07-22T00:37:31.279Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:31.270390026Z","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: 241, tv_nsec: 543625787 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-07-22T00:37:31.304Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:31.270956352Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-07-22T00:37:31.304Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:31.273925386Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"2bfe090eb5318ec8c467157018db2429d4df535b"}
1372026-07-22T00:37:31.304Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:31.277531555Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/2bfe090eb5318ec8c467157018db2429d4df535b/crucible-nightly.sha256.txt"}
1382026-07-22T00:37:31.566Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:31.556782613Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-07-22T00:37:32.093Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.084387835Z","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/bf8c4b23210cdb59a04edb16db2221bd93f20e9d/propolis-server.sha256.txt","timeout":"600s"}
1402026-07-22T00:37:32.257Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.247798407Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-07-22T00:37:32.281Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.249241817Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-07-22T00:37:32.281Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.250586768Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-07-22T00:37:32.281Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.250646933Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-07-22T00:37:32.281Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.250678533Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-07-22T00:37:32.281Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.250710274Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-07-22T00:37:32.281Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.253327246Z","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-07-22T00:37:32.281Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.254532442Z","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-07-22T00:37:32.281Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.25641072Z","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-07-22T00:37:32.738Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:32.729155802Z","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-07-22T00:37:32.763Z{"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":912,"time":"2026-07-22T00:37:32.742542568Z","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-07-22T00:37:39.739Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.730989904Z","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-07-22T00:37:39.763Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.732201041Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1532026-07-22T00:37:39.763Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.747503815Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 5.09M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1542026-07-22T00:37:39.763Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.750362941Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-16c39009-281c-4288-8985-bdacaf8256f2\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1552026-07-22T00:37:39.787Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.772750888Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-16c39009-281c-4288-8985-bdacaf8256f2\", \"phd-artifacts/phd-clone-59bd291d-f8da-43dc-b714-79e3f873d604\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1562026-07-22T00:37:39.811Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.794077516Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-59bd291d-f8da-43dc-b714-79e3f873d604\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1572026-07-22T00:37:39.835Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.804468727Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-59bd291d-f8da-43dc-b714-79e3f873d604 0B 25.3T 49.0M /phd-artifacts/phd-clone-59bd291d-f8da-43dc-b714-79e3f873d604\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1582026-07-22T00:37:39.835Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.808658007Z","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-07-22T00:37:39.836Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.808770912Z","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-07-22T00:37:39.836Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.80884358Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/9a996f0b95892135e19a801f12e72c0bb176074e06df0c0823f2c75489ec900f/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1612026-07-22T00:37:39.836Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:39.808921078Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/bf8c4b23210cdb59a04edb16db2221bd93f20e9d/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1622026-07-22T00:37:52.736Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:52.727780495Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/9a996f0b95892135e19a801f12e72c0bb176074e06df0c0823f2c75489ec900f/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632026-07-22T00:37:52.736Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:37:52.727855826Z","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-07-22T00:38:14.390Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:14.383317896Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/9a996f0b95892135e19a801f12e72c0bb176074e06df0c0823f2c75489ec900f/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-07-22T00:38:14.390Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:14.383431883Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1662026-07-22T00:38:14.563Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 917","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:14.555982869Z","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-07-22T00:38:14.587Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:14.570972628Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1682026-07-22T00:38:14.587Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:14.579625197Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1692026-07-22T00:38:14.611Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:14.583868047Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":34771,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1702026-07-22T00:38:15.315Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.308013561Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-07-22T00:38:15.361Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.310338541Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: e551c047-dcf2-45c3-b15a-cb8f5bf1867b, name: \"phd-vm-e551c047-dcf2-45c3-b15a-cb8f5bf1867b\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 395a1f73-9c93-4255-8c90-5f87f4f908ba, project_id: 50979968-1e77-4392-8101-2bdbe0b4fc6d, sled_id: 1a26d3c8-0a5e-42eb-abce-cb300a671049, sled_serial: \"1a26d3c8-0a5e-42eb-abce-cb300a671049\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1722026-07-22T00:38:15.361Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.31086907Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1732026-07-22T00:38:15.361Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.310925427Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1742026-07-22T00:38:15.361Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.313217992Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":2,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1752026-07-22T00:38:15.362Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.31334255Z","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-07-22T00:38:15.362Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.313822774Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","vm":"migration_from_base","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1772026-07-22T00:38:15.362Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.313875565Z","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-07-22T00:38:15.362Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.313922544Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1792026-07-22T00:38:15.362Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:15.313973201Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1802026-07-22T00:38:19.869Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.863192593Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4548,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1812026-07-22T00:38:19.869Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.863282334Z","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-07-22T00:38:19.894Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.865636015Z","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-07-22T00:38:19.894Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.86569133Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1842026-07-22T00:38:19.894Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.865732188Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1852026-07-22T00:38:19.919Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.892932131Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":27,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1862026-07-22T00:38:19.919Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.893083179Z","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-07-22T00:38:19.919Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.893495504Z","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-07-22T00:38:19.919Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.893552743Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1892026-07-22T00:38:19.919Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.89360353Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1902026-07-22T00:38:19.944Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.926578882Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1912026-07-22T00:38:19.944Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.92669835Z","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-07-22T00:38:19.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.926774475Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4612,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1932026-07-22T00:38:19.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.927660653Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1942026-07-22T00:38:19.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.928119637Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1952026-07-22T00:38:19.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.937358262Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1962026-07-22T00:38:19.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.937600083Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1972026-07-22T00:38:19.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.937696186Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1982026-07-22T00:38:19.976Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.970598498Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
1992026-07-22T00:38:20.001Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.970911865Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2002026-07-22T00:38:20.001Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.971797322Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2012026-07-22T00:38:20.001Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.981421945Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2022026-07-22T00:38:20.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.981716792Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2032026-07-22T00:38:20.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:19.981813396Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2042026-07-22T00:38:20.026Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.014693707Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2052026-07-22T00:38:20.026Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.014948803Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2062026-07-22T00:38:20.026Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.015064634Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2072026-07-22T00:38:20.052Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.025573168Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2082026-07-22T00:38:20.052Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.02587369Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2092026-07-22T00:38:20.052Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.02598926Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2102026-07-22T00:38:20.076Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.058153627Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2112026-07-22T00:38:20.076Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.058450703Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2122026-07-22T00:38:20.076Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.058572415Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2132026-07-22T00:38:20.076Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.069355122Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2142026-07-22T00:38:20.077Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.06965365Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2152026-07-22T00:38:20.077Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.069761195Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2162026-07-22T00:38:20.108Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.102408432Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2172026-07-22T00:38:20.133Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.102716388Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2182026-07-22T00:38:20.133Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.102821268Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2192026-07-22T00:38:20.133Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.113569556Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2202026-07-22T00:38:20.133Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.113789152Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2212026-07-22T00:38:20.134Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.113877577Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2222026-07-22T00:38:20.158Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.146021704Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2232026-07-22T00:38:20.158Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.147080322Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2242026-07-22T00:38:20.158Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.147135337Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2252026-07-22T00:38:20.182Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.157586158Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2262026-07-22T00:38:20.182Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.157817078Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2272026-07-22T00:38:20.182Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.157910796Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2282026-07-22T00:38:20.207Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.191150822Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2292026-07-22T00:38:20.207Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.191898426Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2302026-07-22T00:38:20.207Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.192048963Z","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-07-22T00:38:20.207Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.192097916Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2322026-07-22T00:38:20.207Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.193211277Z","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-07-22T00:38:20.207Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.193274557Z","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-07-22T00:38:20.207Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.193321677Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2352026-07-22T00:38:20.207Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.193382914Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2362026-07-22T00:38:20.240Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 918","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.234785546Z","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-07-22T00:38:20.265Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.247971287Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":55,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2382026-07-22T00:38:20.265Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.248053023Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2392026-07-22T00:38:20.265Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.248116865Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"52a87cb7-3d47-4f35-a273-1ed63ca756a4","target_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2402026-07-22T00:38:20.265Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.248175586Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","source":"migration_from_base"}
2412026-07-22T00:38:20.266Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.248688884Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","source":"migration_from_base"}
2422026-07-22T00:38:20.517Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:20.510723834Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","source":"migration_from_base"}
2432026-07-22T00:38:21.218Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:21.212217386Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 25a525da-1211-42f2-8faa-1fb8ca0e19c1, name: \"phd-vm-25a525da-1211-42f2-8faa-1fb8ca0e19c1\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 395a1f73-9c93-4255-8c90-5f87f4f908ba, project_id: 50979968-1e77-4392-8101-2bdbe0b4fc6d, sled_id: 00c2c31f-252b-4392-a065-bde7e4c7bf2b, sled_serial: \"00c2c31f-252b-4392-a065-bde7e4c7bf2b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","source":"migration_from_base"}
2442026-07-22T00:38:21.242Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:21.213315287Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","migration_id":"52a87cb7-3d47-4f35-a273-1ed63ca756a4","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2452026-07-22T00:38:24.084Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:24.078715907Z","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}}"}
2462026-07-22T00:38:25.101Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:25.095331673Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2472026-07-22T00:38:25.102Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:25.095425211Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","elapsed_milliseconds":3881,"target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","migration_id":"52a87cb7-3d47-4f35-a273-1ed63ca756a4","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2482026-07-22T00:38:25.126Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:25.098483336Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2492026-07-22T00:38:25.126Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:25.100020881Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2502026-07-22T00:38:25.126Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:25.100089665Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2512026-07-22T00:38:25.126Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:25.103609208Z","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":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2522026-07-22T00:38:25.191Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:25.186184974Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":84,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2532026-07-22T00:38:25.216Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:25.186365057Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10614,"vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b"}
2542026-07-22T00:38:26.225Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.218561638Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":1118,"vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2552026-07-22T00:38:26.249Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.218870306Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2562026-07-22T00:38:26.249Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.218992779Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2572026-07-22T00:38:26.276Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.251594991Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2582026-07-22T00:38:26.276Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.252186407Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2592026-07-22T00:38:26.276Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.252377875Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2602026-07-22T00:38:26.276Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.252487885Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10943}
2612026-07-22T00:38:26.276Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.253624815Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2622026-07-22T00:38:26.276Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.253724114Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2632026-07-22T00:38:26.276Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.253909808Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2642026-07-22T00:38:26.701Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.69470099Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2652026-07-22T00:38:26.786Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.780620505Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2662026-07-22T00:38:26.786Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.780700147Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-59bd291d-f8da-43dc-b714-79e3f873d604\"]","verb":"destroy","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2672026-07-22T00:38:26.812Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.806817488Z","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":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2682026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.806875128Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-16c39009-281c-4288-8985-bdacaf8256f2\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2692026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.826361318Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":573,"vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1"}
2702026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827114342Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","elapsed_milliseconds":6578,"source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","vm":"migration_from_base_lifecycle_0","vm_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","target":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2712026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827198693Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"25a525da-1211-42f2-8faa-1fb8ca0e19c1","elapsed_milliseconds":6578,"target":"migration_from_base_lifecycle_0","source_id":"e551c047-dcf2-45c3-b15a-cb8f5bf1867b","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base"}
2722026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827248588Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":54567,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2732026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827285418Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":573}
2742026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827384006Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2752026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827447647Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2762026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.82750178Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2772026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827681593Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2782026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827791372Z","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"}
2792026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.82785357Z","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-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827909056Z","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"}
2812026-07-22T00:38:26.838Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.827973649Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::serial_history"}
2822026-07-22T00:38:26.863Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.839454636Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.07G 25.3T 1.07G /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2832026-07-22T00:38:26.863Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.839573883Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-4a6cbfd2-3359-4b73-8235-e5665ba8ede2\"]","path":"phd_tests::migrate::from_base::serial_history"}
2842026-07-22T00:38:26.863Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.856037578Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-4a6cbfd2-3359-4b73-8235-e5665ba8ede2\", \"phd-artifacts/phd-clone-86e8a0ef-32b9-4444-a0b1-aed5945dacce\"]","path":"phd_tests::migrate::from_base::serial_history"}
2852026-07-22T00:38:26.888Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.874943547Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-86e8a0ef-32b9-4444-a0b1-aed5945dacce\"]","path":"phd_tests::migrate::from_base::serial_history"}
2862026-07-22T00:38:26.913Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.88672899Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-86e8a0ef-32b9-4444-a0b1-aed5945dacce 0B 25.3T 1.07G /phd-artifacts/phd-clone-86e8a0ef-32b9-4444-a0b1-aed5945dacce\n","path":"phd_tests::migrate::from_base::serial_history"}
2872026-07-22T00:38:26.913Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.887546727Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2882026-07-22T00:38:26.913Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.887618103Z","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_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2892026-07-22T00:38:26.913Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.887688287Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/9a996f0b95892135e19a801f12e72c0bb176074e06df0c0823f2c75489ec900f/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2902026-07-22T00:38:26.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.887756407Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/9a996f0b95892135e19a801f12e72c0bb176074e06df0c0823f2c75489ec900f/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
2912026-07-22T00:38:26.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.887829927Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2922026-07-22T00:38:26.939Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 927","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.931077703Z","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"}
2932026-07-22T00:38:26.963Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.945471456Z","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":57}
2942026-07-22T00:38:26.963Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.945595953Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
2952026-07-22T00:38:26.963Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:26.94633989Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
2962026-07-22T00:38:27.781Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.775178061Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2972026-07-22T00:38:27.829Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.776434484Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 0de13bb4-c8cd-4fdb-922d-a96c668ec488, name: \"phd-vm-0de13bb4-c8cd-4fdb-922d-a96c668ec488\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: a5f74110-da9b-4173-ab03-a7748477d587, project_id: 7a77f467-7fca-4e30-987c-1fa5f195c70f, sled_id: 2803592d-7db5-4312-b7a1-ad67ee27444b, sled_serial: \"2803592d-7db5-4312-b7a1-ad67ee27444b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
2982026-07-22T00:38:27.830Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.776593618Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
2992026-07-22T00:38:27.830Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.776651297Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3002026-07-22T00:38:27.830Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.777757735Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":1,"path":"phd_tests::migrate::from_base::serial_history"}
3012026-07-22T00:38:27.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.777839891Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3022026-07-22T00:38:27.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.777898944Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","timeout_duration":"300s","path":"phd_tests::migrate::from_base::serial_history"}
3032026-07-22T00:38:27.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.77795485Z","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"}
3042026-07-22T00:38:27.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.777997952Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3052026-07-22T00:38:27.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:27.778045333Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3062026-07-22T00:38:32.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.387942345Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":4609,"path":"phd_tests::migrate::from_base::serial_history"}
3072026-07-22T00:38:32.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.388030883Z","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"}
3082026-07-22T00:38:32.417Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.388224041Z","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"}
3092026-07-22T00:38:32.418Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.388276782Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3102026-07-22T00:38:32.418Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.388316437Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3112026-07-22T00:38:32.418Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.406281072Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":17,"path":"phd_tests::migrate::from_base::serial_history"}
3122026-07-22T00:38:32.418Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.40638545Z","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"}
3132026-07-22T00:38:32.418Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.406706021Z","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"}
3142026-07-22T00:38:32.418Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.406812975Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3152026-07-22T00:38:32.418Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.406890863Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3162026-07-22T00:38:32.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.439100847Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history"}
3172026-07-22T00:38:32.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.439260381Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3182026-07-22T00:38:32.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.439336777Z","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":4660}
3192026-07-22T00:38:32.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.439603465Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3202026-07-22T00:38:32.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.439717582Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3212026-07-22T00:38:32.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.450461132Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history"}
3222026-07-22T00:38:32.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.450692953Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3232026-07-22T00:38:32.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.450787283Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3242026-07-22T00:38:32.493Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.48277816Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history"}
3252026-07-22T00:38:32.493Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.482970742Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3262026-07-22T00:38:32.493Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.483093711Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3272026-07-22T00:38:32.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.494468014Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::serial_history"}
3282026-07-22T00:38:32.517Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.494589455Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3292026-07-22T00:38:32.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.49463892Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3302026-07-22T00:38:32.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.526898769Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history"}
3312026-07-22T00:38:32.549Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.534194203Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3322026-07-22T00:38:32.549Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.534330011Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3332026-07-22T00:38:32.549Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.534381279Z","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"}
3342026-07-22T00:38:32.549Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.534445702Z","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"}
3352026-07-22T00:38:32.549Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.534503482Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::serial_history"}
3362026-07-22T00:38:32.549Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.534602921Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
3372026-07-22T00:38:32.585Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.580671791Z","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"}
3382026-07-22T00:38:32.609Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.593398158Z","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":59}
3392026-07-22T00:38:32.609Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.593513167Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base"}
3402026-07-22T00:38:32.609Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.593584693Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"966cbee6-002e-4e75-85e9-b3a4011861cd","source_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base"}
3412026-07-22T00:38:32.609Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.593643936Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","vm":"migration_serial_history_base_lifecycle_0","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base"}
3422026-07-22T00:38:32.611Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:32.594242937Z","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":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","vm":"migration_serial_history_base_lifecycle_0","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base"}
3432026-07-22T00:38:33.249Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:33.24403812Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 15f0d525-a13b-47db-a0ef-f912ef2c8925, name: \"phd-vm-15f0d525-a13b-47db-a0ef-f912ef2c8925\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: a5f74110-da9b-4173-ab03-a7748477d587, project_id: 7a77f467-7fca-4e30-987c-1fa5f195c70f, sled_id: 1c3fd34a-f6dc-4ea2-86bd-8be0d7ca0af9, sled_serial: \"1c3fd34a-f6dc-4ea2-86bd-8be0d7ca0af9\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","vm":"migration_serial_history_base_lifecycle_0","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base"}
3442026-07-22T00:38:33.249Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:33.244260513Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","migration_id":"966cbee6-002e-4e75-85e9-b3a4011861cd","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base"}
3452026-07-22T00:38:36.131Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:36.12653647Z","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}}"}
3462026-07-22T00:38:37.709Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.70480941Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base"}
3472026-07-22T00:38:37.709Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.705004031Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","migration_id":"966cbee6-002e-4e75-85e9-b3a4011861cd","elapsed_milliseconds":4460,"path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base"}
3482026-07-22T00:38:37.734Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.707814404Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3492026-07-22T00:38:37.734Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.70955754Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488"}
3502026-07-22T00:38:37.798Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.793968174Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":85,"path":"phd_tests::migrate::from_base::serial_history"}
3512026-07-22T00:38:37.822Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.794240653Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","elapsed_milliseconds":10847,"path":"phd_tests::migrate::from_base::serial_history"}
3522026-07-22T00:38:37.822Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.796978418Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925"}
3532026-07-22T00:38:37.823Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.79718962Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3542026-07-22T00:38:37.823Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.797301483Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3552026-07-22T00:38:37.823Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.797345076Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10020}
3562026-07-22T00:38:37.823Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.797389731Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3572026-07-22T00:38:37.823Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:37.798486911Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925"}
3582026-07-22T00:38:38.091Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.085916684Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925"}
3592026-07-22T00:38:38.174Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.169889271Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925"}
3602026-07-22T00:38:38.174Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.169991425Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-86e8a0ef-32b9-4444-a0b1-aed5945dacce\"]","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925"}
3612026-07-22T00:38:38.199Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.195227588Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925"}
3622026-07-22T00:38:38.200Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.195320505Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-4a6cbfd2-3359-4b73-8235-e5665ba8ede2\"]","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925"}
3632026-07-22T00:38:38.224Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.214589353Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","elapsed_milliseconds":417,"path":"phd_tests::migrate::from_base::serial_history"}
3642026-07-22T00:38:38.224Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.21483109Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","vm":"migration_serial_history_base_lifecycle_0","vm_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","source":"migration_serial_history_base","elapsed_milliseconds":5620,"path":"phd_tests::migrate::from_base::serial_history","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","target":"migration_serial_history_base_lifecycle_0"}
3652026-07-22T00:38:38.224Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.21486806Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":417}
3662026-07-22T00:38:38.224Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.21492237Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0de13bb4-c8cd-4fdb-922d-a96c668ec488","target_id":"15f0d525-a13b-47db-a0ef-f912ef2c8925","elapsed_milliseconds":5620,"path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base"}
3672026-07-22T00:38:38.224Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.214969842Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3682026-07-22T00:38:38.225Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.214971288Z","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":11385}
3692026-07-22T00:38:38.225Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.215023475Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3702026-07-22T00:38:38.225Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.215080414Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3712026-07-22T00:38:38.225Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.215242761Z","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"}
3722026-07-22T00:38:38.225Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.215344637Z","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"}
3732026-07-22T00:38:38.225Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.215406423Z","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-07-22T00:38:38.225Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.215468774Z","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"}
3752026-07-22T00:38:38.225Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.215536834Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-07-22T00:38:38.249Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.227154633Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.07G 25.3T 1.07G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-07-22T00:38:38.249Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.227260555Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-e96089e7-7a04-4527-9326-18475c2eb782\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-07-22T00:38:38.249Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.244452026Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-e96089e7-7a04-4527-9326-18475c2eb782\", \"phd-artifacts/phd-clone-dcad0608-7391-4d29-833e-ea29b801514f\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-07-22T00:38:38.273Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.262410208Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-dcad0608-7391-4d29-833e-ea29b801514f\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-07-22T00:38:38.297Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.274462691Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-dcad0608-7391-4d29-833e-ea29b801514f 0B 25.3T 1.07G /phd-artifacts/phd-clone-dcad0608-7391-4d29-833e-ea29b801514f\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3812026-07-22T00:38:38.297Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.275072383Z","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"}
3822026-07-22T00:38:38.297Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.275139581Z","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","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-07-22T00:38:38.297Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.275217138Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/9a996f0b95892135e19a801f12e72c0bb176074e06df0c0823f2c75489ec900f/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-07-22T00:38:38.297Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.275281431Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/9a996f0b95892135e19a801f12e72c0bb176074e06df0c0823f2c75489ec900f/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-07-22T00:38:38.297Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.27535431Z","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"}
3862026-07-22T00:38:38.326Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 937","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.321425694Z","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"}
3872026-07-22T00:38:38.350Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.335544724Z","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":60}
3882026-07-22T00:38:38.350Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.335666045Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
3892026-07-22T00:38:38.350Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.336381467Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
3902026-07-22T00:38:38.870Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.865319746Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3912026-07-22T00:38:38.916Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.866516616Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: f5c5a0dd-59c4-48ad-b502-95dcd6e70514, name: \"phd-vm-f5c5a0dd-59c4-48ad-b502-95dcd6e70514\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 51019603-7fcc-4f51-bf7f-ce844ba90e9d, project_id: c2e2362b-060b-47c5-ae8d-efc06832f9ac, sled_id: 24267afb-14af-4d2d-8a3f-60ee46103c51, sled_serial: \"24267afb-14af-4d2d-8a3f-60ee46103c51\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
3922026-07-22T00:38:38.916Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.866683954Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
3932026-07-22T00:38:38.916Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.866738188Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
3942026-07-22T00:38:38.916Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.867759473Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":1,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3952026-07-22T00:38:38.916Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.867861127Z","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"}
3962026-07-22T00:38:38.916Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.867919979Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972026-07-22T00:38:38.917Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.867966257Z","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"}
3982026-07-22T00:38:38.917Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.868008347Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
3992026-07-22T00:38:38.917Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:38.868069033Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4002026-07-22T00:38:43.485Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.481048476Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":4612,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4012026-07-22T00:38:43.486Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.481150421Z","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"}
4022026-07-22T00:38:43.510Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.481373966Z","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"}
4032026-07-22T00:38:43.510Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.481439682Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4042026-07-22T00:38:43.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.481488505Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4052026-07-22T00:38:43.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.499120425Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":17,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4062026-07-22T00:38:43.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.499289457Z","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"}
4072026-07-22T00:38:43.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.499696452Z","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"}
4082026-07-22T00:38:43.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.499791771Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4092026-07-22T00:38:43.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.499843366Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4102026-07-22T00:38:43.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.532981927Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4112026-07-22T00:38:43.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.533118142Z","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"}
4122026-07-22T00:38:43.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.533207798Z","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":4664}
4132026-07-22T00:38:43.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.533523074Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4142026-07-22T00:38:43.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.533596293Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4152026-07-22T00:38:43.563Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.543960302Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4162026-07-22T00:38:43.563Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.54420589Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4172026-07-22T00:38:43.563Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.544307614Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4182026-07-22T00:38:43.588Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.577520348Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4192026-07-22T00:38:43.588Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.577828234Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4202026-07-22T00:38:43.588Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.577945948Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4212026-07-22T00:38:43.614Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.589397729Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4222026-07-22T00:38:43.614Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.589644499Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4232026-07-22T00:38:43.614Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.58970258Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4242026-07-22T00:38:43.640Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.622670908Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4252026-07-22T00:38:43.640Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.622916276Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4262026-07-22T00:38:43.640Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.623012809Z","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::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4272026-07-22T00:38:43.640Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.633608347Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4282026-07-22T00:38:43.640Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.633748635Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4292026-07-22T00:38:43.640Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.633800093Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4302026-07-22T00:38:43.664Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.656766506Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4312026-07-22T00:38:43.665Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.656933502Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4322026-07-22T00:38:43.665Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.656985867Z","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::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4332026-07-22T00:38:43.689Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.667417077Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4342026-07-22T00:38:43.689Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.667653487Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4352026-07-22T00:38:43.689Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.667751223Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4362026-07-22T00:38:43.715Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.70094447Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4372026-07-22T00:38:43.715Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.701185699Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4382026-07-22T00:38:43.715Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.701283064Z","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::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4392026-07-22T00:38:43.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.711982342Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4402026-07-22T00:38:43.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.712314254Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4412026-07-22T00:38:43.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.712405738Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4422026-07-22T00:38:43.764Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.745822401Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4432026-07-22T00:38:43.764Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.746145667Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4442026-07-22T00:38:43.764Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.746249244Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4452026-07-22T00:38:43.764Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.756607777Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4462026-07-22T00:38:43.764Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.756837508Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4472026-07-22T00:38:43.764Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.756929267Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4482026-07-22T00:38:43.790Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.77967821Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4492026-07-22T00:38:43.790Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.779863453Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-07-22T00:38:43.790Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.779994312Z","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"}
4512026-07-22T00:38:43.790Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.780039718Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4522026-07-22T00:38:43.790Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.780098871Z","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"}
4532026-07-22T00:38:43.790Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.780144999Z","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::migration_from_base_and_back"}
4542026-07-22T00:38:43.791Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.780210083Z","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"}
4552026-07-22T00:38:43.824Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.819952082Z","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"}
4562026-07-22T00:38:43.848Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.83285775Z","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":52}
4572026-07-22T00:38:43.849Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.832938985Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","target":"migration_from_base_and_back_lifecycle_0"}
4582026-07-22T00:38:43.849Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.832996534Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"6f2641dc-8eed-49fa-8f04-f4d7ceda3a50","timeout_duration":"45s","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","target":"migration_from_base_and_back_lifecycle_0"}
4592026-07-22T00:38:43.849Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.833060085Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0"}
4602026-07-22T00:38:43.849Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:43.833624029Z","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)","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0"}
4612026-07-22T00:38:44.666Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:44.661407612Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 2afe02a3-babe-44d6-bde9-ef1548bcb351, name: \"phd-vm-2afe02a3-babe-44d6-bde9-ef1548bcb351\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 51019603-7fcc-4f51-bf7f-ce844ba90e9d, project_id: c2e2362b-060b-47c5-ae8d-efc06832f9ac, sled_id: 682260d0-32a4-41e7-80b3-fa05b56027d7, sled_serial: \"682260d0-32a4-41e7-80b3-fa05b56027d7\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0"}
4622026-07-22T00:38:44.691Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:44.661727081Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","target":"migration_from_base_and_back_lifecycle_0","migration_id":"6f2641dc-8eed-49fa-8f04-f4d7ceda3a50"}
4632026-07-22T00:38:47.527Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:47.523231931Z","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}}"}
4642026-07-22T00:38:48.834Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.830247788Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","target":"migration_from_base_and_back_lifecycle_0"}
4652026-07-22T00:38:48.834Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.830304987Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":4168,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","target":"migration_from_base_and_back_lifecycle_0","migration_id":"6f2641dc-8eed-49fa-8f04-f4d7ceda3a50"}
4662026-07-22T00:38:48.859Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.832907885Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4672026-07-22T00:38:48.859Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.833133976Z","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":"migration_from_base_and_back_lifecycle_0","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351"}
4682026-07-22T00:38:48.859Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.833191996Z","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":"migration_from_base_and_back_lifecycle_0","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351"}
4692026-07-22T00:38:48.859Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.834454278Z","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":"migration_from_base_and_back","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514"}
4702026-07-22T00:38:48.923Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.919995784Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":86,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4712026-07-22T00:38:48.947Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.920264686Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":10583,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4722026-07-22T00:38:48.948Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.920396627Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","elapsed_milliseconds":87,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4732026-07-22T00:38:48.948Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.92059769Z","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":"migration_from_base_and_back_lifecycle_0","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351"}
4742026-07-22T00:38:48.948Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.920662854Z","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":"migration_from_base_and_back_lifecycle_0","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351"}
4752026-07-22T00:38:48.972Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.955041409Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","elapsed_milliseconds":34,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4762026-07-22T00:38:48.972Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.955231872Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__BASE_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772026-07-22T00:38:48.972Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.955375946Z","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"}
4782026-07-22T00:38:48.972Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.955466449Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_1","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-07-22T00:38:48.973Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.955575486Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/9a996f0b95892135e19a801f12e72c0bb176074e06df0c0823f2c75489ec900f/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-07-22T00:38:48.973Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.955669025Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/9a996f0b95892135e19a801f12e72c0bb176074e06df0c0823f2c75489ec900f/propolis-server\"","server_addr":"127.0.0.1:9004","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-07-22T00:38:48.973Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.95577161Z","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"}
4822026-07-22T00:38:49.003Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 940","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:48.999354915Z","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"}
4832026-07-22T00:38:49.027Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:49.013829442Z","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":58}
4842026-07-22T00:38:49.027Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:49.013933991Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","target":"migration_from_base_and_back_lifecycle_1"}
4852026-07-22T00:38:49.028Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:49.014015336Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"10de2a61-0be1-4485-8ea6-1d52094891b5","timeout_duration":"45s","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","target":"migration_from_base_and_back_lifecycle_1"}
4862026-07-22T00:38:49.028Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:49.014086501Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1"}
4872026-07-22T00:38:49.028Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:49.01467361Z","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)","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1"}
4882026-07-22T00:38:49.861Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:49.857005309Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: d2eba21a-00a7-4a89-8d93-16bd66b29aff, name: \"phd-vm-d2eba21a-00a7-4a89-8d93-16bd66b29aff\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 51019603-7fcc-4f51-bf7f-ce844ba90e9d, project_id: c2e2362b-060b-47c5-ae8d-efc06832f9ac, sled_id: 45f94d68-ba84-49ec-8ca2-762742422c71, sled_serial: \"45f94d68-ba84-49ec-8ca2-762742422c71\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1"}
4892026-07-22T00:38:49.862Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:49.857224136Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","target":"migration_from_base_and_back_lifecycle_1","migration_id":"10de2a61-0be1-4485-8ea6-1d52094891b5"}
4902026-07-22T00:38:52.829Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.825747885Z","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}}"}
4912026-07-22T00:38:52.896Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.892532186Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","target":"migration_from_base_and_back_lifecycle_1"}
4922026-07-22T00:38:52.921Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.892611587Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","elapsed_milliseconds":3034,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","target":"migration_from_base_and_back_lifecycle_1","migration_id":"10de2a61-0be1-4485-8ea6-1d52094891b5"}
4932026-07-22T00:38:52.921Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.89455046Z","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":"migration_from_base_and_back_lifecycle_0","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351"}
4942026-07-22T00:38:52.921Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.894792812Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff"}
4952026-07-22T00:38:52.921Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.894855201Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff"}
4962026-07-22T00:38:52.921Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.896161389Z","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":"migration_from_base_and_back_lifecycle_0","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351"}
4972026-07-22T00:38:52.990Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.986644886Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","elapsed_milliseconds":91,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4982026-07-22T00:38:53.015Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.98680992Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":9152,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","vm":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_0"}
4992026-07-22T00:38:53.015Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:52.986908357Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"f5c5a0dd-59c4-48ad-b502-95dcd6e70514","elapsed_milliseconds":9152,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","target":"migration_from_base_and_back_lifecycle_0"}
5002026-07-22T00:38:53.769Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.765731104Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","elapsed_milliseconds":870,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5012026-07-22T00:38:53.795Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.766042697Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff"}
5022026-07-22T00:38:53.795Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.76614902Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff"}
5032026-07-22T00:38:53.820Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.800227683Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","elapsed_milliseconds":34,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5042026-07-22T00:38:53.820Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.800364504Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5052026-07-22T00:38:53.820Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.80047252Z","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"}
5062026-07-22T00:38:53.820Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.800517064Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5072026-07-22T00:38:53.820Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.800573833Z","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"}
5082026-07-22T00:38:53.820Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.800620962Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-07-22T00:38:53.820Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.800691597Z","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"}
5102026-07-22T00:38:53.848Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 942","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.844335983Z","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"}
5112026-07-22T00:38:53.873Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.858533958Z","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":58}
5122026-07-22T00:38:53.873Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.858615023Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","target":"migration_from_base_and_back_lifecycle_2"}
5132026-07-22T00:38:53.873Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.858674526Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"941d1740-042a-4a76-b1eb-eba1f21c364f","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","target":"migration_from_base_and_back_lifecycle_2"}
5142026-07-22T00:38:53.873Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.858729471Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2"}
5152026-07-22T00:38:53.873Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:53.859309405Z","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)","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2"}
5162026-07-22T00:38:54.535Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:54.531325568Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 2fa39bf8-2f0e-4a7d-965d-7be0ad258eef, name: \"phd-vm-2fa39bf8-2f0e-4a7d-965d-7be0ad258eef\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 51019603-7fcc-4f51-bf7f-ce844ba90e9d, project_id: c2e2362b-060b-47c5-ae8d-efc06832f9ac, sled_id: ac11e890-1e90-4d72-8bf3-5aa7da26fa40, sled_serial: \"ac11e890-1e90-4d72-8bf3-5aa7da26fa40\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2"}
5172026-07-22T00:38:54.535Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:54.531505191Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","target":"migration_from_base_and_back_lifecycle_2","migration_id":"941d1740-042a-4a76-b1eb-eba1f21c364f"}
5182026-07-22T00:38:57.417Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:57.414122127Z","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}}"}
5192026-07-22T00:38:58.575Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.572021892Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","target":"migration_from_base_and_back_lifecycle_2"}
5202026-07-22T00:38:58.575Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.572100622Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","elapsed_milliseconds":4040,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","target":"migration_from_base_and_back_lifecycle_2","migration_id":"941d1740-042a-4a76-b1eb-eba1f21c364f"}
5212026-07-22T00:38:58.599Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.574309908Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff"}
5222026-07-22T00:38:58.600Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.57452602Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5232026-07-22T00:38:58.600Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.574583539Z","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::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5242026-07-22T00:38:58.600Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.576613215Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff"}
5252026-07-22T00:38:58.665Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.662423873Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","elapsed_milliseconds":87,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5262026-07-22T00:38:58.690Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.662734375Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","elapsed_milliseconds":88,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5272026-07-22T00:38:58.690Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.662714998Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","elapsed_milliseconds":9647,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","vm":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_1"}
5282026-07-22T00:38:58.690Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.662896844Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"2afe02a3-babe-44d6-bde9-ef1548bcb351","elapsed_milliseconds":9647,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","target":"migration_from_base_and_back_lifecycle_1"}
5292026-07-22T00:38:58.690Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.662960385Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5302026-07-22T00:38:58.690Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.663048303Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5312026-07-22T00:38:58.715Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.686915297Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","elapsed_milliseconds":23,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5322026-07-22T00:38:58.715Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.687049663Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5332026-07-22T00:38:58.715Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.687253191Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5342026-07-22T00:38:58.715Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.68739952Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":19819}
5352026-07-22T00:38:58.715Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.687441139Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5362026-07-22T00:38:58.715Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.687571117Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5372026-07-22T00:38:58.715Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.688726532Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5382026-07-22T00:38:58.992Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:58.989525951Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5392026-07-22T00:38:59.076Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.073171225Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5402026-07-22T00:38:59.076Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.073303236Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-dcad0608-7391-4d29-833e-ea29b801514f\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5412026-07-22T00:38:59.102Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.099140634Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5422026-07-22T00:38:59.102Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.099203764Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-e96089e7-7a04-4527-9326-18475c2eb782\"]","verb":"destroy","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef"}
5432026-07-22T00:38:59.127Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.117691445Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","elapsed_milliseconds":430,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5442026-07-22T00:38:59.127Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.117977259Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":430}
5452026-07-22T00:38:59.127Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.118090575Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5462026-07-22T00:38:59.127Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.118013268Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","elapsed_milliseconds":5258,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","vm":"migration_from_base_and_back_lifecycle_2","target":"migration_from_base_and_back_lifecycle_2"}
5472026-07-22T00:38:59.127Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.11813532Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5482026-07-22T00:38:59.127Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 86.86s
5492026-07-22T00:38:59.127Z
5502026-07-22T00:38:59.127Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.118137244Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"d2eba21a-00a7-4a89-8d93-16bd66b29aff","elapsed_milliseconds":5258,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"2fa39bf8-2f0e-4a7d-965d-7be0ad258eef","target":"migration_from_base_and_back_lifecycle_2"}
5512026-07-22T00:38:59.127Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.11819274Z","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":20900}
5522026-07-22T00:38:59.127Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-07-22T00:38:59.118246943Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5532026-07-22T00:38:59.241Z
5542026-07-22T00:38:59.241Zreal 1:28.090484646
5552026-07-22T00:38:59.241Zuser 48.991878221
5562026-07-22T00:38:59.241Zsys 21.342615653
5572026-07-22T00:38:59.266Ztrap 0.006926125
5582026-07-22T00:38:59.266Ztflt 0.005070993
5592026-07-22T00:38:59.266Zdflt 0.003907095
5602026-07-22T00:38:59.266Zkflt 0.000000000
5612026-07-22T00:38:59.266Zlock 3:27:48.233075781
5622026-07-22T00:38:59.266Zslp 4:30.722289190
5632026-07-22T00:38:59.266Zlat 2.101753253
5642026-07-22T00:38:59.266Zstop 52.015709124
5652026-07-22T00:38:59.266Z+ failcount=0
5662026-07-22T00:38:59.266Z+ set -e
5672026-07-22T00:38:59.266Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5682026-07-22T00:38:59.291ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5692026-07-22T00:38:59.291Za ./ 0K
5702026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5712026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 158K
5722026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5732026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5742026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 164K
5752026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5762026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::serial_history/ 0K
5772026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 158K
5782026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5792026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5802026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 165K
5812026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5822026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5832026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 158K
5842026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5852026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5862026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 269K
5872026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5882026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 269K
5892026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5902026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 164K
5912026-07-22T00:38:59.291Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5922026-07-22T00:38:59.291Z+ exitcode=0
5932026-07-22T00:38:59.291Z+ '[' 0 -eq 0 ']'
5942026-07-22T00:38:59.291Z+ echo
5952026-07-22T00:38:59.291Z+ echo 'ALL TESTS PASSED'
5962026-07-22T00:38:59.292Z
5972026-07-22T00:38:59.292ZALL TESTS PASSED
5982026-07-22T00:38:59.292Z+ echo
5992026-07-22T00:38:59.292Z
6002026-07-22T00:38:59.292Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6012026-07-22T00:38:59.292Z+ read
6022026-07-22T00:38:59.292Z+ exit 0
6032026-07-22T00:38:59.292Zprocess exited: duration 144886 ms, exit code 0
 
6042026-07-22T00:38:59.344Zfound 2 output files
6052026-07-22T00:38:59.372Zuploading: /tmp/phd-runner.log (185122 bytes)
6062026-07-22T00:39:00.489Zuploaded: /tmp/phd-runner.log
6072026-07-22T00:39:00.489Zuploading: /tmp/phd-tmp-files.tar.gz (133101 bytes)
6082026-07-22T00:39:01.672Zuploaded: /tmp/phd-tmp-files.tar.gz