01KPRQ3M363DMQWD5Z8X1AJK14: 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: 01KPRQ418MXC0PDYM9RS4D4KDG

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-04-21T19:19:15.153Zjob dependencies complete; ready to run (waiting for 10 m 22 s)
22026-04-21T19:22:41.557Zjob assigned to worker 01KPRQQ1MXK2F7BV1H47A4AWXR [factory edgar, gimlet/BRM42220060/414] (queued for 3 m 26 s)
32026-04-21T19:22:42.300Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-04-21T19:22:42.340Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-04-21T19:22:42.340Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-04-21T19:22:42.394Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-04-21T19:22:42.394Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-04-21T19:22:48.130Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-04-21T19:22:48.130Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-04-21T19:22:48.179Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-04-21T19:22:48.179Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-04-21T19:22:57.912Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-04-21T19:22:57.912Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-04-21T19:23:06.073Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-04-21T19:23:06.073Zstarting task 0: "setup"
162026-04-21T19:23:06.098Z++ uname -s
172026-04-21T19:23:06.098Z+ kern=SunOS
182026-04-21T19:23:06.098Z+ build_user=build
192026-04-21T19:23:06.098Z+ build_uid=12345
202026-04-21T19:23:06.099Z+ work_dir=/work
212026-04-21T19:23:06.099Z+ input_dir=/input
222026-04-21T19:23:06.099Z+ [[ 0 == 12345 ]]
232026-04-21T19:23:06.099Z+ case "$kern" in
242026-04-21T19:23:06.099Z+ groupadd -g 12345 build
252026-04-21T19:23:06.099Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-04-21T19:23:08.107Z+ zfs create -o mountpoint=/work rpool/work
272026-04-21T19:23:08.137Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-04-21T19:23:08.161Z+ home_fs=
292026-04-21T19:23:08.161Z+ [[ '' == autofs ]]
302026-04-21T19:23:08.161Z+ mkdir -p /home/build
312026-04-21T19:23:08.161Z+ chown build:build /home/build /work
322026-04-21T19:23:10.150Z+ chmod 0700 /home/build /work
332026-04-21T19:23:10.175Zprocess exited: duration 4081 ms, exit code 0
 
342026-04-21T19:23:10.224Zstarting task 1: "authentication"
352026-04-21T19:23:10.294Zprocess exited: duration 70 ms, exit code 0
 
362026-04-21T19:23:10.345Zstarting task 2: "build"
372026-04-21T19:23:10.372Z+ indir=/input
382026-04-21T19:23:10.372Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-04-21T19:23:10.372Z+ phddir=/work/phd-test
402026-04-21T19:23:10.372Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-04-21T19:23:10.396Z++ pilot local disk list -H -o type,disk
422026-04-21T19:23:10.396Z++ grep -v M.2
432026-04-21T19:23:10.396Z++ cut -f 2
442026-04-21T19:23:10.447Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC586d0 c9t0014EE81000BC57Cd0 c10t0014EE81000BC3CCd0 c11t0014EE81000BC478d0 c4t0014EE81000BC5BBd0 c3t0014EE81000BC247d0 c2t0014EE81000BC649d0 c6t0014EE81000BC634d0 c5t0014EE81000BC0B1d0
452026-04-21T19:23:10.720Z+ artifactdir=/phd-artifacts
462026-04-21T19:23:10.720Z+ banner Inputs
472026-04-21T19:23:10.745Z ###
482026-04-21T19:23:10.745Z # # # ##### # # ##### ####
492026-04-21T19:23:10.745Z # ## # # # # # # #
502026-04-21T19:23:10.745Z # # # # # # # # # ####
512026-04-21T19:23:10.745Z # # # # ##### # # # #
522026-04-21T19:23:10.745Z # # ## # # # # # #
532026-04-21T19:23:10.746Z ### # # # #### # ####
542026-04-21T19:23:10.746Z
552026-04-21T19:23:10.746Z+ find /input -ls
562026-04-21T19:23:10.746Z 34 1 drwxr-xr-x 3 root root 3 Apr 21 19:22 /input
572026-04-21T19:23:10.746Z 2 1 drwxr-xr-x 3 root root 3 Apr 21 19:22 /input/phd-build
582026-04-21T19:23:10.746Z 3 2 drwxr-xr-x 2 root root 8 Apr 21 19:22 /input/phd-build/out
592026-04-21T19:23:10.746Z 512 205398 -rw-r--r-- 1 root root 210333024 Apr 21 19:22 /input/phd-build/out/propolis-server-debug.tar.gz
602026-04-21T19:23:10.746Z 384 1 -rw-r--r-- 1 root root 65 Apr 21 19:22 /input/phd-build/out/propolis-server-debug.sha256.txt
612026-04-21T19:23:10.746Z 128 2 -rw-r--r-- 1 root root 2573 Apr 21 19:22 /input/phd-build/out/phd-run-with-args.sh
622026-04-21T19:23:10.746Z 256 1 -rw-r--r-- 1 root root 65 Apr 21 19:22 /input/phd-build/out/phd-runner.sha256.txt
632026-04-21T19:23:10.746Z 640 175297 -rw-r--r-- 1 root root 179474393 Apr 21 19:23 /input/phd-build/out/propolis-tests-debug.tar.gz
642026-04-21T19:23:10.746Z 257 117558 -rw-r--r-- 1 root root 120317370 Apr 21 19:22 /input/phd-build/out/phd-runner.tar.gz
652026-04-21T19:23:10.746Z+ rm -rf /work/phd-test
662026-04-21T19:23:10.746Z+ mkdir /work/phd-test
672026-04-21T19:23:10.746Z+ for p in $indir/$indir_suffix
682026-04-21T19:23:10.746Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-04-21T19:23:13.787ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-04-21T19:23:13.787Zx phd-runner, 426501688 bytes, 833012 tape blocks
712026-04-21T19:23:13.787Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-04-21T19:23:13.812Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-04-21T19:23:16.783Z+ for f in $(tar tf "$p")
742026-04-21T19:23:16.783Z+ chmod +x /work/phd-test/phd-runner
752026-04-21T19:23:16.808Z+ for f in $(tar tf "$p")
762026-04-21T19:23:16.808Z+ chmod +x /work/phd-test/artifacts.toml
772026-04-21T19:23:16.808Z+ for p in $indir/$indir_suffix
782026-04-21T19:23:16.808Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-04-21T19:23:27.016ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-04-21T19:23:27.016Zx propolis-server, 800538688 bytes, 1563553 tape blocks
812026-04-21T19:23:27.041Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-04-21T19:23:32.438Z+ for f in $(tar tf "$p")
832026-04-21T19:23:32.438Z+ chmod +x /work/phd-test/propolis-server
842026-04-21T19:23:32.463Z+ for p in $indir/$indir_suffix
852026-04-21T19:23:32.463Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-04-21T19:23:46.645ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-04-21T19:23:46.645Zx target/debug/deps/propolis-6e59630620340148, 682340992 bytes, 1332698 tape blocks
882026-04-21T19:23:46.669Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-04-21T19:23:50.917Z+ for f in $(tar tf "$p")
902026-04-21T19:23:50.917Z+ chmod +x /work/phd-test/target/debug/deps/propolis-6e59630620340148
912026-04-21T19:23:50.942Z+ ls /work/phd-test
922026-04-21T19:23:50.942Zartifacts.toml
932026-04-21T19:23:50.942Zphd-runner
942026-04-21T19:23:50.942Zpropolis-server
952026-04-21T19:23:50.942Ztarget
962026-04-21T19:23:50.942Z+ banner Setup
972026-04-21T19:23:50.942Z #####
982026-04-21T19:23:50.942Z# # ###### ##### # # #####
992026-04-21T19:23:50.942Z# # # # # # #
1002026-04-21T19:23:50.942Z ##### ##### # # # # #
1012026-04-21T19:23:50.942Z # # # # # #####
1022026-04-21T19:23:50.942Z# # # # # # #
1032026-04-21T19:23:50.942Z ##### ###### # #### #
1042026-04-21T19:23:50.942Z
1052026-04-21T19:23:50.942Z+ tmpdir=/tmp/propolis-phd
1062026-04-21T19:23:50.942Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-04-21T19:23:50.942Z+ mkdir /tmp/propolis-phd
1082026-04-21T19:23:50.942Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-04-21T19:23:51.410Z+ banner Tests
1102026-04-21T19:23:51.435Z#######
1112026-04-21T19:23:51.435Z # ###### #### ##### ####
1122026-04-21T19:23:51.435Z # # # # #
1132026-04-21T19:23:51.435Z # ##### #### # ####
1142026-04-21T19:23:51.435Z # # # # #
1152026-04-21T19:23:51.435Z # # # # # # #
1162026-04-21T19:23:51.435Z # ###### #### # ####
1172026-04-21T19:23:51.435Z
1182026-04-21T19:23:51.435Z+ runner=/work/phd-test/phd-runner
1192026-04-21T19:23:51.435Z+ artifacts=/work/phd-test/artifacts.toml
1202026-04-21T19:23:51.435Z+ propolis=/work/phd-test/propolis-server
1212026-04-21T19:23:51.435Z+ ls /work/phd-test/phd-runner
1222026-04-21T19:23:51.435Z/work/phd-test/phd-runner
1232026-04-21T19:23:51.435Z+ ls /work/phd-test/artifacts.toml
1242026-04-21T19:23:51.435Z/work/phd-test/artifacts.toml
1252026-04-21T19:23:51.435Z+ ls /work/phd-test/propolis-server
1262026-04-21T19:23:51.435Z/work/phd-test/propolis-server
1272026-04-21T19:23:51.435Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-04-21T19:23:51.435Z+ set +e
1292026-04-21T19:23:51.435Z+ RUST_BACKTRACE=1
1302026-04-21T19:23:51.435Z+ RUST_LOG=info,phd=debug
1312026-04-21T19:23:51.435Z+ 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-04-21T19:23:51.435Z+ tee /tmp/phd-runner.log
1332026-04-21T19:23:51.659Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:51.64535341Z","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-04-21T19:23:51.685Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:51.679723372Z","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: 221, tv_nsec: 470734235 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-04-21T19:23:51.685Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:51.67984819Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-04-21T19:23:51.709Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:51.683580008Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"ae1da83e66c648574827298f4bc444632bf4d047"}
1372026-04-21T19:23:51.709Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:51.686437488Z","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/ae1da83e66c648574827298f4bc444632bf4d047/crucible-nightly.sha256.txt"}
1382026-04-21T19:23:51.885Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:51.879814599Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-04-21T19:23:52.417Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.412214978Z","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/aa17344cb3b82bef8812863d9fb666cacd3f2a92/propolis-server.sha256.txt","timeout":"600s"}
1402026-04-21T19:23:52.567Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.562797621Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-04-21T19:23:52.592Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.562863522Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-04-21T19:23:52.592Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.563714609Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-04-21T19:23:52.592Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.563779122Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-04-21T19:23:52.592Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.563810201Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-04-21T19:23:52.592Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.56384095Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-04-21T19:23:52.592Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.566147739Z","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-04-21T19:23:52.592Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.567507549Z","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-04-21T19:23:52.592Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.569748198Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1492026-04-21T19:23:52.983Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:52.978974447Z","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-04-21T19:23:53.008Z{"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":824,"time":"2026-04-21T19:23:52.993655238Z","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-04-21T19:23:59.548Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.546719156Z","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-04-21T19:23:59.549Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.546874441Z","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-04-21T19:23:59.574Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.560325651Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2.09M 25.3T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1542026-04-21T19:23:59.574Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.560742529Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-4274d1f9-589a-40f7-8c3e-0879abe0a6b1\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1552026-04-21T19:23:59.600Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.584246771Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-4274d1f9-589a-40f7-8c3e-0879abe0a6b1\", \"phd-artifacts/phd-clone-b59acbbf-bf32-4322-8a72-0b6cb0748497\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1562026-04-21T19:23:59.625Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.600307817Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-b59acbbf-bf32-4322-8a72-0b6cb0748497\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1572026-04-21T19:23:59.625Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.611813801Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-b59acbbf-bf32-4322-8a72-0b6cb0748497 0B 25.3T 48.9M /phd-artifacts/phd-clone-b59acbbf-bf32-4322-8a72-0b6cb0748497\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1582026-04-21T19:23:59.625Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.615997919Z","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-04-21T19:23:59.625Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.616075589Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1602026-04-21T19:23:59.625Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.616145105Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/394a00c5b665d3a7840deeebd5c371f4aeff4765d24d3c87ec9b3e91c780f0b4/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1612026-04-21T19:23:59.625Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:23:59.616217693Z","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/aa17344cb3b82bef8812863d9fb666cacd3f2a92/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1622026-04-21T19:24:09.494Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:09.497227424Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/394a00c5b665d3a7840deeebd5c371f4aeff4765d24d3c87ec9b3e91c780f0b4/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632026-04-21T19:24:09.494Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:09.497324058Z","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-04-21T19:24:28.464Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:28.474496156Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/394a00c5b665d3a7840deeebd5c371f4aeff4765d24d3c87ec9b3e91c780f0b4/propolis-server\"","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-04-21T19:24:28.464Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:28.474606504Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1662026-04-21T19:24:28.590Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 829","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:28.600690503Z","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-04-21T19:24:28.615Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:28.614144428Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1682026-04-21T19:24:28.615Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:28.620104657Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1692026-04-21T19:24:28.615Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:28.621191288Z","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","elapsed_milliseconds":28991}
1702026-04-21T19:24:29.143Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.154511929Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-04-21T19:24:29.190Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.157792593Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7, name: \"phd-vm-2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 79594d58-7706-4878-ba59-219497aad3df, project_id: 8f3fbe3b-9f9d-4eb4-ba35-fdb2923b0eff, sled_id: d93a56f6-5230-402c-8def-531383e1d8f5, sled_serial: \"d93a56f6-5230-402c-8def-531383e1d8f5\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1722026-04-21T19:24:29.190Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.157952357Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1732026-04-21T19:24:29.190Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.15800753Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1742026-04-21T19:24:29.191Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.159510554Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":1,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1752026-04-21T19:24:29.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.159610013Z","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-04-21T19:24:29.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.159696006Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","timeout_duration":"300s","vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1772026-04-21T19:24:29.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.160073588Z","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-04-21T19:24:29.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.160124676Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1792026-04-21T19:24:29.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:29.160184658Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1802026-04-21T19:24:33.733Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.747133273Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4584,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1812026-04-21T19:24:33.733Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.747215846Z","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-04-21T19:24:33.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.747456247Z","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-04-21T19:24:33.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.747507213Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1842026-04-21T19:24:33.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.747542877Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1852026-04-21T19:24:33.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.766160561Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":18,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1862026-04-21T19:24:33.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.766306028Z","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-04-21T19:24:33.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.766685115Z","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-04-21T19:24:33.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.766738326Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1892026-04-21T19:24:33.759Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.766774216Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1902026-04-21T19:24:33.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.799034102Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1912026-04-21T19:24:33.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.799179663Z","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-04-21T19:24:33.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.799252806Z","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","elapsed_milliseconds":4637}
1932026-04-21T19:24:33.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.801418089Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1942026-04-21T19:24:33.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.80181025Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1952026-04-21T19:24:33.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.809789771Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":7,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1962026-04-21T19:24:33.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.809905876Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1972026-04-21T19:24:33.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.810021819Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1982026-04-21T19:24:33.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.843108753Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":33,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
1992026-04-21T19:24:33.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.843397812Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2002026-04-21T19:24:33.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.843495228Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2012026-04-21T19:24:33.859Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.854101923Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2022026-04-21T19:24:33.859Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.854320476Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2032026-04-21T19:24:33.859Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.854415456Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2042026-04-21T19:24:33.884Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.886658245Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2052026-04-21T19:24:33.884Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.886974847Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2062026-04-21T19:24:33.884Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.887031725Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2072026-04-21T19:24:33.884Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.897481278Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2082026-04-21T19:24:33.884Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.897716215Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2092026-04-21T19:24:33.885Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.897811146Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2102026-04-21T19:24:33.918Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.930984538Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":33,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2112026-04-21T19:24:33.942Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.931316303Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2122026-04-21T19:24:33.942Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.931370947Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2132026-04-21T19:24:33.942Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.941787173Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2142026-04-21T19:24:33.942Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.942072269Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2152026-04-21T19:24:33.942Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.942128316Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2162026-04-21T19:24:33.967Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.975219317Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":33,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2172026-04-21T19:24:33.967Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.975464614Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2182026-04-21T19:24:33.967Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.975559985Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2192026-04-21T19:24:33.992Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.985940126Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2202026-04-21T19:24:33.992Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.986053572Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2212026-04-21T19:24:33.992Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:33.986109245Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2222026-04-21T19:24:34.017Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.019127842Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2232026-04-21T19:24:34.017Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.01936891Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2242026-04-21T19:24:34.017Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.01945879Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2252026-04-21T19:24:34.017Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.02999548Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2262026-04-21T19:24:34.017Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.030331297Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2272026-04-21T19:24:34.017Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.030386262Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2282026-04-21T19:24:34.049Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.062439056Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2292026-04-21T19:24:34.049Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.062619691Z","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-04-21T19:24:34.074Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.062746494Z","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-04-21T19:24:34.075Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.062853395Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2322026-04-21T19:24:34.075Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.063681973Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","sha256":"None","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2332026-04-21T19:24:34.075Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.063749852Z","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-04-21T19:24:34.075Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.063801911Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2352026-04-21T19:24:34.075Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.063872375Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2362026-04-21T19:24:34.100Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 830","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.095615097Z","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-04-21T19:24:34.100Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.108487582Z","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","elapsed_milliseconds":45}
2382026-04-21T19:24:34.100Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.108579827Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base"}
2392026-04-21T19:24:34.100Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.10863916Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"bf373ba0-cb99-4d5a-a23d-c348213d0a9d","target":"migration_from_base_lifecycle_0","source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base"}
2402026-04-21T19:24:34.100Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.108693363Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","vm_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base"}
2412026-04-21T19:24:34.100Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.109198505Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","vm_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base"}
2422026-04-21T19:24:34.718Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.731843719Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: e61d7c08-b648-415a-8fa8-18d80f8b218d, name: \"phd-vm-e61d7c08-b648-415a-8fa8-18d80f8b218d\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 79594d58-7706-4878-ba59-219497aad3df, project_id: 8f3fbe3b-9f9d-4eb4-ba35-fdb2923b0eff, sled_id: 686d7aa4-6e9f-4bbb-b7ce-38ec103161cc, sled_serial: \"686d7aa4-6e9f-4bbb-b7ce-38ec103161cc\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","vm_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base"}
2432026-04-21T19:24:34.743Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:34.732606466Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","path":"phd_tests::migrate::from_base::can_migrate_from_base","migration_id":"bf373ba0-cb99-4d5a-a23d-c348213d0a9d","target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base"}
2442026-04-21T19:24:37.427Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:37.442593043Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
2452026-04-21T19:24:38.973Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:38.989063209Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base"}
2462026-04-21T19:24:38.973Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:38.989135155Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":4254,"source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","path":"phd_tests::migrate::from_base::can_migrate_from_base","migration_id":"bf373ba0-cb99-4d5a-a23d-c348213d0a9d","target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base"}
2472026-04-21T19:24:38.998Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:38.990959954Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2482026-04-21T19:24:38.998Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:38.992107265Z","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":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2492026-04-21T19:24:38.998Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:38.992165472Z","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":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2502026-04-21T19:24:38.998Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:38.994695765Z","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":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2512026-04-21T19:24:39.066Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.08276006Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":89,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2522026-04-21T19:24:39.091Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.08294633Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10463,"vm_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7"}
2532026-04-21T19:24:39.091Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.083193381Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":90,"vm_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2542026-04-21T19:24:39.091Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.083459246Z","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":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2552026-04-21T19:24:39.091Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.083586394Z","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":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2562026-04-21T19:24:39.117Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.116878849Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":33,"vm_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2572026-04-21T19:24:39.117Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.117059122Z","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":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2582026-04-21T19:24:39.117Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.117368751Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2592026-04-21T19:24:39.117Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.117522583Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2602026-04-21T19:24:39.117Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.117573149Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9958}
2612026-04-21T19:24:39.117Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.117627691Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2622026-04-21T19:24:39.117Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.118859654Z","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":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2632026-04-21T19:24:39.774Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.790089417Z","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":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2642026-04-21T19:24:39.852Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.868441357Z","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":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2652026-04-21T19:24:39.852Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.868524655Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-b59acbbf-bf32-4322-8a72-0b6cb0748497\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2662026-04-21T19:24:39.878Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.894924628Z","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":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2672026-04-21T19:24:39.903Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.894988876Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-4274d1f9-589a-40f7-8c3e-0879abe0a6b1\"]","verb":"destroy","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2682026-04-21T19:24:39.903Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.912476419Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":794,"vm_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2692026-04-21T19:24:39.903Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913103112Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","elapsed_milliseconds":5801,"vm_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d"}
2702026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913170931Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source_id":"2423bfb7-e0b4-4f9b-9f03-e3e6002d44e7","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":5801,"target_id":"e61d7c08-b648-415a-8fa8-18d80f8b218d","source":"migration_from_base"}
2712026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.91322285Z","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","elapsed_milliseconds":47323}
2722026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913203373Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":795}
2732026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913300437Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2742026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.9133441Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2752026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913381081Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2762026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913539382Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2772026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913638741Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
2782026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913698775Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::serial_history"}
2792026-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913751265Z","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-04-21T19:24:39.904Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.913818132Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::serial_history"}
2812026-04-21T19:24:39.929Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.924984797Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1013M 25.3T 1013M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2822026-04-21T19:24:39.929Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.925132809Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-3edf25e8-6192-4455-bd29-211361996c99\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::serial_history"}
2832026-04-21T19:24:39.929Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.944388161Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-3edf25e8-6192-4455-bd29-211361996c99\", \"phd-artifacts/phd-clone-a5b5a799-56e8-4064-b8b9-916fb3e7f79e\"]","verb":"clone","path":"phd_tests::migrate::from_base::serial_history"}
2842026-04-21T19:24:39.954Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.960553369Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-a5b5a799-56e8-4064-b8b9-916fb3e7f79e\"]","path":"phd_tests::migrate::from_base::serial_history"}
2852026-04-21T19:24:39.978Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.971565288Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-a5b5a799-56e8-4064-b8b9-916fb3e7f79e 0B 25.3T 1013M /phd-artifacts/phd-clone-a5b5a799-56e8-4064-b8b9-916fb3e7f79e\n","path":"phd_tests::migrate::from_base::serial_history"}
2862026-04-21T19:24:39.978Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.97228075Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2872026-04-21T19:24:39.978Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.972345904Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_serial_history_base","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
2882026-04-21T19:24:39.978Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.972413302Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/394a00c5b665d3a7840deeebd5c371f4aeff4765d24d3c87ec9b3e91c780f0b4/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2892026-04-21T19:24:39.978Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.972477244Z","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/394a00c5b665d3a7840deeebd5c371f4aeff4765d24d3c87ec9b3e91c780f0b4/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
2902026-04-21T19:24:39.978Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:39.972550303Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2912026-04-21T19:24:40.003Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 839","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.007489337Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
2922026-04-21T19:24:40.028Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.021385042Z","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":49}
2932026-04-21T19:24:40.028Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.021483395Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2942026-04-21T19:24:40.028Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.0222103Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2952026-04-21T19:24:40.678Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.694756911Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2962026-04-21T19:24:40.727Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.695785013Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 9d488a6c-3eb2-4869-8419-f8565f94e26e, name: \"phd-vm-9d488a6c-3eb2-4869-8419-f8565f94e26e\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 776eee40-edde-4ca2-b801-dc26fad36c0f, project_id: ae0265e2-036e-4bb4-979b-a8497dadf6f7, sled_id: b7b39e88-4959-489c-b130-9eb2ad66837d, sled_serial: \"b7b39e88-4959-489c-b130-9eb2ad66837d\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2972026-04-21T19:24:40.727Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.695937504Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2982026-04-21T19:24:40.727Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.695995644Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2992026-04-21T19:24:40.727Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.696951566Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":0,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3002026-04-21T19:24:40.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.697025525Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3012026-04-21T19:24:40.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.697077693Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","timeout_duration":"300s","path":"phd_tests::migrate::from_base::serial_history"}
3022026-04-21T19:24:40.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.697119585Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
3032026-04-21T19:24:40.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.697157579Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3042026-04-21T19:24:40.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:40.697202787Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3052026-04-21T19:24:45.167Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.185041575Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":4485,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3062026-04-21T19:24:45.167Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.185129041Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
3072026-04-21T19:24:45.167Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.18531119Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3082026-04-21T19:24:45.167Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.185369631Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3092026-04-21T19:24:45.167Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.185418865Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3102026-04-21T19:24:45.193Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.204327729Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":18,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3112026-04-21T19:24:45.193Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.204475621Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3122026-04-21T19:24:45.193Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.204791632Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3132026-04-21T19:24:45.193Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.20486412Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3142026-04-21T19:24:45.193Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.204909215Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3152026-04-21T19:24:45.219Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.2372238Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":32,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3162026-04-21T19:24:45.219Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.237361882Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3172026-04-21T19:24:45.219Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.237431996Z","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":4538}
3182026-04-21T19:24:45.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.23772335Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3192026-04-21T19:24:45.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.237835723Z","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_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3202026-04-21T19:24:45.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.248404592Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":10,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3212026-04-21T19:24:45.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.248638217Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3222026-04-21T19:24:45.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.248733057Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3232026-04-21T19:24:45.269Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.281905924Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":33,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3242026-04-21T19:24:45.269Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.282168383Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3252026-04-21T19:24:45.269Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.282266281Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3262026-04-21T19:24:45.294Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.293749609Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":11,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3272026-04-21T19:24:45.294Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.293982011Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3282026-04-21T19:24:45.294Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.2940761Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3292026-04-21T19:24:45.318Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.325949401Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":31,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3302026-04-21T19:24:45.319Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.331562397Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_serial_history_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::serial_history"}
3312026-04-21T19:24:45.319Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.331681814Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3322026-04-21T19:24:45.319Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.331727962Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3332026-04-21T19:24:45.319Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.331787626Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
3342026-04-21T19:24:45.319Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.331838612Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history"}
3352026-04-21T19:24:45.319Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.331914988Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
3362026-04-21T19:24:45.348Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 840","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.365893048Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
3372026-04-21T19:24:45.373Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.379082604Z","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":47}
3382026-04-21T19:24:45.373Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.379167848Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history"}
3392026-04-21T19:24:45.373Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.379227211Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"a1eef854-521f-4be8-bfd2-7a410c9db2e9","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history"}
3402026-04-21T19:24:45.373Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.379286965Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3412026-04-21T19:24:45.373Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:45.379846789Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3422026-04-21T19:24:46.017Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:46.035077457Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 61c7f538-d204-42ec-b2d1-e801d9826edc, name: \"phd-vm-61c7f538-d204-42ec-b2d1-e801d9826edc\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 776eee40-edde-4ca2-b801-dc26fad36c0f, project_id: ae0265e2-036e-4bb4-979b-a8497dadf6f7, sled_id: 414fdfb5-b03b-409f-ae7c-b6ba4f65cf1a, sled_serial: \"414fdfb5-b03b-409f-ae7c-b6ba4f65cf1a\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3432026-04-21T19:24:46.043Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:46.035275544Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","migration_id":"a1eef854-521f-4be8-bfd2-7a410c9db2e9","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history"}
3442026-04-21T19:24:48.666Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:48.680116679Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7756}}"}
3452026-04-21T19:24:50.359Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.37240879Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history"}
3462026-04-21T19:24:50.359Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.372481991Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","migration_id":"a1eef854-521f-4be8-bfd2-7a410c9db2e9","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4341}
3472026-04-21T19:24:50.384Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.374977852Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3482026-04-21T19:24:50.384Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.37673643Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3492026-04-21T19:24:50.458Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.47075553Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":95,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3502026-04-21T19:24:50.482Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.471035011Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":10452,"vm_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","path":"phd_tests::migrate::from_base::serial_history"}
3512026-04-21T19:24:50.482Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.473968576Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3522026-04-21T19:24:50.482Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.474160451Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3532026-04-21T19:24:50.482Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.474302Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9782}
3542026-04-21T19:24:50.482Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.474289967Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3552026-04-21T19:24:50.482Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.474385681Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3562026-04-21T19:24:50.482Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:50.475737254Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3572026-04-21T19:24:51.105Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.117788564Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3582026-04-21T19:24:51.178Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.19100739Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3592026-04-21T19:24:51.178Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.191125955Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-a5b5a799-56e8-4064-b8b9-916fb3e7f79e\"]","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3602026-04-21T19:24:51.205Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.216411066Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3612026-04-21T19:24:51.205Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.216499725Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-3edf25e8-6192-4455-bd29-211361996c99\"]","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3622026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.232357341Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":758,"vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history"}
3632026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.232538676Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","vm_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","vm":"migration_serial_history_base_lifecycle_0","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","elapsed_milliseconds":5858}
3642026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.232606214Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":758}
3652026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.232629208Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","source_id":"9d488a6c-3eb2-4869-8419-f8565f94e26e","target_id":"61c7f538-d204-42ec-b2d1-e801d9826edc","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":5858}
3662026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.232718099Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3672026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.232705946Z","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":11322}
3682026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.232760199Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3692026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.23279758Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3702026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.232988914Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3712026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.233126756Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3722026-04-21T19:24:51.230Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.233220835Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3732026-04-21T19:24:51.231Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.23331272Z","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-04-21T19:24:51.231Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.233408041Z","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"}
3752026-04-21T19:24:51.255Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.244981452Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1013M 25.3T 1013M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-04-21T19:24:51.255Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.245135896Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-1d97fc18-f265-4eaa-ae20-64a499bbedbc\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-04-21T19:24:51.255Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.26591404Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-1d97fc18-f265-4eaa-ae20-64a499bbedbc\", \"phd-artifacts/phd-clone-7279dd6c-7749-4eff-8316-b6a534697e8f\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-04-21T19:24:51.280Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.284208905Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-7279dd6c-7749-4eff-8316-b6a534697e8f\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-04-21T19:24:51.304Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.296818528Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-7279dd6c-7749-4eff-8316-b6a534697e8f 0B 25.3T 1013M /phd-artifacts/phd-clone-7279dd6c-7749-4eff-8316-b6a534697e8f\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-04-21T19:24:51.304Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.297485948Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3812026-04-21T19:24:51.305Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.297547174Z","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","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-04-21T19:24:51.305Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.297619834Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/394a00c5b665d3a7840deeebd5c371f4aeff4765d24d3c87ec9b3e91c780f0b4/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-04-21T19:24:51.305Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.297679358Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/394a00c5b665d3a7840deeebd5c371f4aeff4765d24d3c87ec9b3e91c780f0b4/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-04-21T19:24:51.305Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.297763257Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-04-21T19:24:51.330Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 849","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.332387764Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3862026-04-21T19:24:51.355Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.346270581Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":48,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3872026-04-21T19:24:51.355Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.346387263Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
3882026-04-21T19:24:51.355Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:51.347060876Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
3892026-04-21T19:24:52.132Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.143742885Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3902026-04-21T19:24:52.179Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.144880092Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: eebf44a9-0202-4907-b7d0-72ccb72da7db, name: \"phd-vm-eebf44a9-0202-4907-b7d0-72ccb72da7db\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: e4b976e8-3e34-40bc-a361-8873f1e6bb6a, project_id: 8632e8bc-4056-4bd1-8d42-dbc41ec58ea1, sled_id: f92ed968-3b3c-40f4-b2a6-45626f2c0f50, sled_serial: \"f92ed968-3b3c-40f4-b2a6-45626f2c0f50\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
3912026-04-21T19:24:52.180Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.14503683Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
3922026-04-21T19:24:52.180Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.14508937Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
3932026-04-21T19:24:52.180Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.146144479Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":1}
3942026-04-21T19:24:52.180Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.14622925Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3952026-04-21T19:24:52.180Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.146295846Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-04-21T19:24:52.180Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.146346112Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972026-04-21T19:24:52.180Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.146389294Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
3982026-04-21T19:24:52.180Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:52.146437446Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
3992026-04-21T19:24:56.657Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.663612333Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":4521}
4002026-04-21T19:24:56.657Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.663699359Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012026-04-21T19:24:56.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.663899098Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4022026-04-21T19:24:56.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.663987837Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4032026-04-21T19:24:56.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.664042692Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4042026-04-21T19:24:56.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.681974925Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":17}
4052026-04-21T19:24:56.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.682096346Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4062026-04-21T19:24:56.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.682431824Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4072026-04-21T19:24:56.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.682543026Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4082026-04-21T19:24:56.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.682631516Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4092026-04-21T19:24:56.707Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.714540505Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":31}
4102026-04-21T19:24:56.707Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.714657089Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4112026-04-21T19:24:56.707Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.714729066Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4572,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4122026-04-21T19:24:56.732Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.714982548Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4132026-04-21T19:24:56.732Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.715087006Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4142026-04-21T19:24:56.732Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.72566894Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":10}
4152026-04-21T19:24:56.732Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.725909247Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4162026-04-21T19:24:56.732Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.726011782Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4172026-04-21T19:24:56.757Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.758941126Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":32}
4182026-04-21T19:24:56.757Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.759182565Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4192026-04-21T19:24:56.757Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.759277936Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4202026-04-21T19:24:56.781Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.76967573Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":10}
4212026-04-21T19:24:56.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.76991244Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4222026-04-21T19:24:56.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.77000705Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4232026-04-21T19:24:56.806Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.792059949Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":22}
4242026-04-21T19:24:56.806Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.79225458Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4252026-04-21T19:24:56.806Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.792316758Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4262026-04-21T19:24:56.806Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.803821659Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":11}
4272026-04-21T19:24:56.806Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.804070692Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4282026-04-21T19:24:56.806Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.804172857Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4292026-04-21T19:24:56.831Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.836245166Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":32}
4302026-04-21T19:24:56.831Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.83648782Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4312026-04-21T19:24:56.831Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.836585065Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4322026-04-21T19:24:56.856Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.847097506Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":10}
4332026-04-21T19:24:56.856Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.847339907Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4342026-04-21T19:24:56.856Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.847396705Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4352026-04-21T19:24:56.881Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.880295519Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":32}
4362026-04-21T19:24:56.881Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.880611031Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4372026-04-21T19:24:56.881Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.880716241Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4382026-04-21T19:24:56.905Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.891044382Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":10}
4392026-04-21T19:24:56.905Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.891270943Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4402026-04-21T19:24:56.905Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.891362727Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4412026-04-21T19:24:56.930Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.924036653Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":32}
4422026-04-21T19:24:56.930Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.924278263Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4432026-04-21T19:24:56.930Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.924331504Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4442026-04-21T19:24:56.930Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.935866011Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":11}
4452026-04-21T19:24:56.930Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.936169448Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4462026-04-21T19:24:56.930Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.936272113Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4472026-04-21T19:24:56.962Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.969221024Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":32}
4482026-04-21T19:24:56.962Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.969359059Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4492026-04-21T19:24:56.987Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.969480479Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-04-21T19:24:56.987Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.969558768Z","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_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-04-21T19:24:56.987Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.969674929Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4522026-04-21T19:24:56.987Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.969759771Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-04-21T19:24:56.987Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:56.969896761Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-04-21T19:24:57.012Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 850","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:57.001354394Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4552026-04-21T19:24:57.012Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:57.014570491Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":45,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4562026-04-21T19:24:57.012Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:57.014650663Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4572026-04-21T19:24:57.012Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:57.014712591Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"6d51545c-cdcc-43d7-8656-9b518b132b83","timeout_duration":"45s","target_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4582026-04-21T19:24:57.012Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:57.014773166Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4592026-04-21T19:24:57.012Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:57.015291444Z","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":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4602026-04-21T19:24:57.737Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:57.742762715Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c8ccee4a-7dae-4612-ab04-77fdd5ba47c2, name: \"phd-vm-c8ccee4a-7dae-4612-ab04-77fdd5ba47c2\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: e4b976e8-3e34-40bc-a361-8873f1e6bb6a, project_id: 8632e8bc-4056-4bd1-8d42-dbc41ec58ea1, sled_id: 77bec290-79a3-4b94-b302-05bffa51bc26, sled_serial: \"77bec290-79a3-4b94-b302-05bffa51bc26\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4612026-04-21T19:24:57.737Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:24:57.742937066Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","migration_id":"6d51545c-cdcc-43d7-8656-9b518b132b83","source":"migration_from_base_and_back","source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4622026-04-21T19:25:00.395Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:00.398276474Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
4632026-04-21T19:25:01.251Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:01.254187629Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4642026-04-21T19:25:01.251Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:01.254263733Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","migration_id":"6d51545c-cdcc-43d7-8656-9b518b132b83","source":"migration_from_base_and_back","elapsed_milliseconds":3514,"source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4652026-04-21T19:25:01.276Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:01.256048591Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4662026-04-21T19:25:01.276Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:01.256265153Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4672026-04-21T19:25:01.276Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:01.256318024Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4682026-04-21T19:25:01.276Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:01.258357556Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4692026-04-21T19:25:01.347Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:01.349312195Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":93}
4702026-04-21T19:25:01.371Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:01.349554766Z","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":"eebf44a9-0202-4907-b7d0-72ccb72da7db","elapsed_milliseconds":10012}
4712026-04-21T19:25:02.998Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:02.999037498Z","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":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","elapsed_milliseconds":1744}
4722026-04-21T19:25:03.023Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:02.999357537Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4732026-04-21T19:25:03.023Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:02.999414766Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4742026-04-21T19:25:03.048Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.032370259Z","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":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","elapsed_milliseconds":32}
4752026-04-21T19:25:03.048Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.032503352Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__BASE_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762026-04-21T19:25:03.048Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.032622519Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772026-04-21T19:25:03.048Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.032709065Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-04-21T19:25:03.048Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.032821128Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/394a00c5b665d3a7840deeebd5c371f4aeff4765d24d3c87ec9b3e91c780f0b4/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-04-21T19:25:03.048Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.032915688Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/394a00c5b665d3a7840deeebd5c371f4aeff4765d24d3c87ec9b3e91c780f0b4/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-04-21T19:25:03.048Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.03304299Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-04-21T19:25:03.073Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 852","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.065138925Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4822026-04-21T19:25:03.097Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.078015637Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":45,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4832026-04-21T19:25:03.098Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.078092974Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4842026-04-21T19:25:03.098Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.078155573Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"cb8a2654-ae35-4708-8e36-26b9cc7db796","timeout_duration":"45s","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4852026-04-21T19:25:03.098Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.078215206Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4862026-04-21T19:25:03.098Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.078709027Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4872026-04-21T19:25:03.595Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.594687962Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: e4e31f3e-d12d-446d-b527-3f7c75b789cb, name: \"phd-vm-e4e31f3e-d12d-446d-b527-3f7c75b789cb\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: e4b976e8-3e34-40bc-a361-8873f1e6bb6a, project_id: 8632e8bc-4056-4bd1-8d42-dbc41ec58ea1, sled_id: feb393a6-b0a2-4b79-823d-5455c6909ccc, sled_serial: \"feb393a6-b0a2-4b79-823d-5455c6909ccc\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4882026-04-21T19:25:03.595Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:03.594885147Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","migration_id":"cb8a2654-ae35-4708-8e36-26b9cc7db796","source":"migration_from_base_and_back_lifecycle_0","source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4892026-04-21T19:25:06.317Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:06.314918826Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7894}}"}
4902026-04-21T19:25:07.286Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.284246304Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4912026-04-21T19:25:07.286Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.284330795Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","migration_id":"cb8a2654-ae35-4708-8e36-26b9cc7db796","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":3691,"source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4922026-04-21T19:25:07.311Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.286365232Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4932026-04-21T19:25:07.311Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.286598425Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
4942026-04-21T19:25:07.311Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.286664952Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
4952026-04-21T19:25:07.311Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.288028915Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
4962026-04-21T19:25:07.369Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.367849891Z","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":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","elapsed_milliseconds":81}
4972026-04-21T19:25:07.395Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.36818575Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","target_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","elapsed_milliseconds":10361}
4982026-04-21T19:25:07.395Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.36830119Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","elapsed_milliseconds":10361,"source_id":"eebf44a9-0202-4907-b7d0-72ccb72da7db"}
4992026-04-21T19:25:07.395Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.368462066Z","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":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","elapsed_milliseconds":81}
5002026-04-21T19:25:07.395Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.368790781Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5012026-04-21T19:25:07.395Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.36891117Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5022026-04-21T19:25:07.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.396742924Z","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":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","elapsed_milliseconds":27}
5032026-04-21T19:25:07.420Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.396879187Z","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"}
5042026-04-21T19:25:07.420Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.397019938Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5052026-04-21T19:25:07.420Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.397105358Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_2","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-04-21T19:25:07.420Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.397216447Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5072026-04-21T19:25:07.420Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.397308168Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9006","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-04-21T19:25:07.420Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.397451326Z","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_2.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-04-21T19:25:07.445Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 854","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.432598885Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5102026-04-21T19:25:07.470Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.446033177Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":48,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5112026-04-21T19:25:07.470Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.446119742Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5122026-04-21T19:25:07.470Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.446180664Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"316065c0-45db-4217-89a9-100ee89cba0d","timeout_duration":"45s","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5132026-04-21T19:25:07.470Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.446248499Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5142026-04-21T19:25:07.470Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.446906425Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5152026-04-21T19:25:07.929Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.927800431Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: b11ba952-824a-42fe-8f9f-f8749abdd324, name: \"phd-vm-b11ba952-824a-42fe-8f9f-f8749abdd324\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: e4b976e8-3e34-40bc-a361-8873f1e6bb6a, project_id: 8632e8bc-4056-4bd1-8d42-dbc41ec58ea1, sled_id: 21078869-a59a-4010-a8c8-ed12ca83c979, sled_serial: \"21078869-a59a-4010-a8c8-ed12ca83c979\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5162026-04-21T19:25:07.955Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:07.927978285Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","migration_id":"316065c0-45db-4217-89a9-100ee89cba0d","source":"migration_from_base_and_back_lifecycle_1","source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5172026-04-21T19:25:10.590Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:10.589535253Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7941}}"}
5182026-04-21T19:25:12.310Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.309914821Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5192026-04-21T19:25:12.336Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.30999822Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","migration_id":"316065c0-45db-4217-89a9-100ee89cba0d","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":4380,"source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5202026-04-21T19:25:12.336Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.312023134Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5212026-04-21T19:25:12.336Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.31231553Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5222026-04-21T19:25:12.336Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.312375554Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5232026-04-21T19:25:12.336Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.313693841Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5242026-04-21T19:25:12.405Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.404614868Z","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":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","elapsed_milliseconds":92}
5252026-04-21T19:25:12.430Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.404947629Z","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":"b11ba952-824a-42fe-8f9f-f8749abdd324","elapsed_milliseconds":92}
5262026-04-21T19:25:12.430Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.404895066Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","elapsed_milliseconds":9326}
5272026-04-21T19:25:12.430Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.405036852Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":9327,"source_id":"c8ccee4a-7dae-4612-ab04-77fdd5ba47c2"}
5282026-04-21T19:25:12.430Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.405181032Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5292026-04-21T19:25:12.430Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.405326623Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5302026-04-21T19:25:12.455Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.438336558Z","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":"b11ba952-824a-42fe-8f9f-f8749abdd324","elapsed_milliseconds":33}
5312026-04-21T19:25:12.455Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.438448321Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5322026-04-21T19:25:12.455Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.438614386Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5332026-04-21T19:25:12.455Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.438746838Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":20305}
5342026-04-21T19:25:12.455Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.438835577Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5352026-04-21T19:25:12.455Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.438957198Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5362026-04-21T19:25:12.455Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.440138223Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5372026-04-21T19:25:12.794Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.79425592Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5382026-04-21T19:25:12.871Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.871134896Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5392026-04-21T19:25:12.871Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.871224119Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-7279dd6c-7749-4eff-8316-b6a534697e8f\"]","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5402026-04-21T19:25:12.897Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.897587822Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5412026-04-21T19:25:12.897Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.897654887Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-1d97fc18-f265-4eaa-ae20-64a499bbedbc\"]","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324"}
5422026-04-21T19:25:12.922Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.915892435Z","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":"b11ba952-824a-42fe-8f9f-f8749abdd324","elapsed_milliseconds":477}
5432026-04-21T19:25:12.922Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.916107705Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":476}
5442026-04-21T19:25:12.922Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.916131149Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","elapsed_milliseconds":5467}
5452026-04-21T19:25:12.922Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.916207815Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5462026-04-21T19:25:12.922Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.916207615Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"b11ba952-824a-42fe-8f9f-f8749abdd324","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":5467,"source_id":"e4e31f3e-d12d-446d-b527-3f7c75b789cb"}
5472026-04-21T19:25:12.922Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.91624738Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5482026-04-21T19:25:12.922Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 80.34s
5492026-04-21T19:25:12.922Z
5502026-04-21T19:25:12.922Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.916259072Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":21694,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5512026-04-21T19:25:12.922Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220060","pid":824,"time":"2026-04-21T19:25:12.916851645Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5522026-04-21T19:25:13.028Z
5532026-04-21T19:25:13.028Zreal 1:21.486219705
5542026-04-21T19:25:13.028Zuser 44.084227536
5552026-04-21T19:25:13.028Zsys 20.341972324
5562026-04-21T19:25:13.028Ztrap 0.006762832
5572026-04-21T19:25:13.028Ztflt 0.004988297
5582026-04-21T19:25:13.053Zdflt 0.003279022
5592026-04-21T19:25:13.053Zkflt 0.000000000
5602026-04-21T19:25:13.053Zlock 3:13:31.493161222
5612026-04-21T19:25:13.054Zslp 4:17.977684520
5622026-04-21T19:25:13.054Zlat 1.613314651
5632026-04-21T19:25:13.054Zstop 37.574699924
5642026-04-21T19:25:13.054Z+ failcount=0
5652026-04-21T19:25:13.054Z+ set -e
5662026-04-21T19:25:13.054Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5672026-04-21T19:25:13.054ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5682026-04-21T19:25:13.054Za ./ 0K
5692026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5702026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 141K
5712026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5722026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5732026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 147K
5742026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5752026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::serial_history/ 0K
5762026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 141K
5772026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5782026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5792026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 147K
5802026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5812026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5822026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 141K
5832026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5842026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5852026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 235K
5862026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5872026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 235K
5882026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5892026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 147K
5902026-04-21T19:25:13.054Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5912026-04-21T19:25:13.079Z+ exitcode=0
5922026-04-21T19:25:13.079Z+ '[' 0 -eq 0 ']'
5932026-04-21T19:25:13.079Z+ echo
5942026-04-21T19:25:13.080Z
5952026-04-21T19:25:13.080Z+ echo 'ALL TESTS PASSED'
5962026-04-21T19:25:13.080ZALL TESTS PASSED
5972026-04-21T19:25:13.080Z+ echo
5982026-04-21T19:25:13.080Z
5992026-04-21T19:25:13.080Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6002026-04-21T19:25:13.080Z+ read
6012026-04-21T19:25:13.080Z+ exit 0
6022026-04-21T19:25:13.080Zprocess exited: duration 122710 ms, exit code 0
 
6032026-04-21T19:25:13.161Zfound 2 output files
6042026-04-21T19:25:13.161Zuploading: /tmp/phd-runner.log (184408 bytes)
6052026-04-21T19:25:14.308Zuploaded: /tmp/phd-runner.log
6062026-04-21T19:25:14.309Zuploading: /tmp/phd-tmp-files.tar.gz (106615 bytes)
6072026-04-21T19:25:15.508Zuploaded: /tmp/phd-tmp-files.tar.gz