01KJXT4N0TS11HVYAKVRRHMADY: 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: 01KJXT5T4QSGCQX8N5HMP6QKRM

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-03-05T01:58:37.410Zjob dependencies complete; ready to run (waiting for 22 m 55 s)
22026-03-05T02:36:43.290Zjob assigned to worker 01KJXXFMPZN3AETTFJQT825TH0 [factory edgar, gimlet/BRM42220010/521] (queued for 38 m 5 s)
32026-03-05T02:36:43.903Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-03-05T02:36:43.927Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-03-05T02:36:43.927Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-03-05T02:36:43.956Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-03-05T02:36:43.956Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-03-05T02:36:49.291Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-03-05T02:36:49.291Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-03-05T02:36:49.338Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-03-05T02:36:49.338Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-03-05T02:36:57.262Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
132026-03-05T02:36:57.262Zstarting task 0: "setup"
142026-03-05T02:36:57.288Z++ uname -s
152026-03-05T02:36:57.288Z+ kern=SunOS
162026-03-05T02:36:57.288Z+ build_user=build
172026-03-05T02:36:57.288Z+ build_uid=12345
182026-03-05T02:36:57.288Z+ work_dir=/work
192026-03-05T02:36:57.288Z+ input_dir=/input
202026-03-05T02:36:57.288Z+ [[ 0 == 12345 ]]
212026-03-05T02:36:57.288Z+ case "$kern" in
222026-03-05T02:36:57.288Z+ groupadd -g 12345 build
232026-03-05T02:36:57.288Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
242026-03-05T02:36:59.297Z+ zfs create -o mountpoint=/work rpool/work
252026-03-05T02:36:59.327Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
262026-03-05T02:36:59.352Z+ home_fs=
272026-03-05T02:36:59.352Z+ [[ '' == autofs ]]
282026-03-05T02:36:59.352Z+ mkdir -p /home/build
292026-03-05T02:36:59.352Z+ chown build:build /home/build /work
302026-03-05T02:37:01.340Z+ chmod 0700 /home/build /work
312026-03-05T02:37:01.365Zprocess exited: duration 4083 ms, exit code 0
 
322026-03-05T02:37:01.416Zstarting task 1: "authentication"
332026-03-05T02:37:01.485Zprocess exited: duration 69 ms, exit code 0
 
342026-03-05T02:37:01.535Zstarting task 2: "build"
352026-03-05T02:37:01.562Z+ indir=/input
362026-03-05T02:37:01.562Z+ indir_suffix='phd-build/out/*.tar.gz'
372026-03-05T02:37:01.562Z+ phddir=/work/phd-test
382026-03-05T02:37:01.562Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
392026-03-05T02:37:01.587Z++ pilot local disk list -H -o type,disk
402026-03-05T02:37:01.587Z++ grep -v M.2
412026-03-05T02:37:01.587Z++ cut -f 2
422026-03-05T02:37:01.638Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
432026-03-05T02:37:01.913Z+ artifactdir=/phd-artifacts
442026-03-05T02:37:01.913Z+ banner Inputs
452026-03-05T02:37:01.938Z ###
462026-03-05T02:37:01.938Z # # # ##### # # ##### ####
472026-03-05T02:37:01.938Z # ## # # # # # # #
482026-03-05T02:37:01.938Z # # # # # # # # # ####
492026-03-05T02:37:01.938Z # # # # ##### # # # #
502026-03-05T02:37:01.938Z # # ## # # # # # #
512026-03-05T02:37:01.938Z ### # # # #### # ####
522026-03-05T02:37:01.938Z
532026-03-05T02:37:01.938Z+ find /input -ls
542026-03-05T02:37:01.938Z 34 1 drwxr-xr-x 3 root root 3 Mar 5 02:36 /input
552026-03-05T02:37:01.938Z 2 1 drwxr-xr-x 3 root root 3 Mar 5 02:36 /input/phd-build
562026-03-05T02:37:01.938Z 3 2 drwxr-xr-x 2 root root 7 Mar 5 02:36 /input/phd-build/out
572026-03-05T02:37:01.938Z 256 1 -rw-r--r-- 1 root root 65 Mar 5 02:36 /input/phd-build/out/propolis-server-debug.sha256.txt
582026-03-05T02:37:01.938Z 257 173897 -rw-r--r-- 1 root root 178050582 Mar 5 02:36 /input/phd-build/out/propolis-server-debug.tar.gz
592026-03-05T02:37:01.938Z 129 1 -rw-r--r-- 1 root root 65 Mar 5 02:36 /input/phd-build/out/phd-runner.sha256.txt
602026-03-05T02:37:01.938Z 128 2 -rw-r--r-- 1 root root 2573 Mar 5 02:36 /input/phd-build/out/phd-run-with-args.sh
612026-03-05T02:37:01.938Z 130 113197 -rw-r--r-- 1 root root 115872510 Mar 5 02:36 /input/phd-build/out/phd-runner.tar.gz
622026-03-05T02:37:01.938Z+ rm -rf /work/phd-test
632026-03-05T02:37:01.938Z+ mkdir /work/phd-test
642026-03-05T02:37:01.939Z+ for p in $indir/$indir_suffix
652026-03-05T02:37:01.939Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
662026-03-05T02:37:04.929ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
672026-03-05T02:37:04.929Zx phd-runner, 411951080 bytes, 804592 tape blocks
682026-03-05T02:37:04.929Zx artifacts.toml, 548 bytes, 2 tape blocks
692026-03-05T02:37:04.954Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
702026-03-05T02:37:07.832Z+ for f in $(tar tf "$p")
712026-03-05T02:37:07.832Z+ chmod +x /work/phd-test/phd-runner
722026-03-05T02:37:07.857Z+ for f in $(tar tf "$p")
732026-03-05T02:37:07.857Z+ chmod +x /work/phd-test/artifacts.toml
742026-03-05T02:37:07.857Z+ for p in $indir/$indir_suffix
752026-03-05T02:37:07.857Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
762026-03-05T02:37:17.643ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
772026-03-05T02:37:17.643Zx propolis-server, 679554992 bytes, 1327256 tape blocks
782026-03-05T02:37:17.668Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
792026-03-05T02:37:22.286Z+ for f in $(tar tf "$p")
802026-03-05T02:37:22.286Z+ chmod +x /work/phd-test/propolis-server
812026-03-05T02:37:22.310Z+ ls /work/phd-test
822026-03-05T02:37:22.310Zartifacts.toml
832026-03-05T02:37:22.310Zphd-runner
842026-03-05T02:37:22.310Zpropolis-server
852026-03-05T02:37:22.310Z+ banner Setup
862026-03-05T02:37:22.310Z #####
872026-03-05T02:37:22.310Z# # ###### ##### # # #####
882026-03-05T02:37:22.310Z# # # # # # #
892026-03-05T02:37:22.310Z ##### ##### # # # # #
902026-03-05T02:37:22.310Z # # # # # #####
912026-03-05T02:37:22.310Z# # # # # # #
922026-03-05T02:37:22.310Z ##### ###### # #### #
932026-03-05T02:37:22.310Z
942026-03-05T02:37:22.310Z+ tmpdir=/tmp/propolis-phd
952026-03-05T02:37:22.310Z+ '[' '!' -d /tmp/propolis-phd ']'
962026-03-05T02:37:22.310Z+ mkdir /tmp/propolis-phd
972026-03-05T02:37:22.310Z+ pfexec /usr/lib/rsrvrctl -s 4096
982026-03-05T02:37:22.847Z+ banner Tests
992026-03-05T02:37:22.872Z#######
1002026-03-05T02:37:22.872Z # ###### #### ##### ####
1012026-03-05T02:37:22.872Z # # # # #
1022026-03-05T02:37:22.872Z # ##### #### # ####
1032026-03-05T02:37:22.872Z # # # # #
1042026-03-05T02:37:22.872Z # # # # # # #
1052026-03-05T02:37:22.872Z # ###### #### # ####
1062026-03-05T02:37:22.872Z
1072026-03-05T02:37:22.872Z+ runner=/work/phd-test/phd-runner
1082026-03-05T02:37:22.872Z+ artifacts=/work/phd-test/artifacts.toml
1092026-03-05T02:37:22.872Z+ propolis=/work/phd-test/propolis-server
1102026-03-05T02:37:22.872Z+ ls /work/phd-test/phd-runner
1112026-03-05T02:37:22.872Z/work/phd-test/phd-runner
1122026-03-05T02:37:22.872Z+ ls /work/phd-test/artifacts.toml
1132026-03-05T02:37:22.872Z/work/phd-test/artifacts.toml
1142026-03-05T02:37:22.872Z+ ls /work/phd-test/propolis-server
1152026-03-05T02:37:22.872Z/work/phd-test/propolis-server
1162026-03-05T02:37:22.872Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1172026-03-05T02:37:22.872Z+ set +e
1182026-03-05T02:37:22.872Z+ RUST_BACKTRACE=1
1192026-03-05T02:37:22.872Z+ RUST_LOG=info,phd=debug
1202026-03-05T02:37:22.872Z+ 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
1212026-03-05T02:37:22.872Z+ tee /tmp/phd-runner.log
1222026-03-05T02:37:23.065Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:23.044478134Z","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 }), disable_ansi: false, emit_bunyan: true }"}
1232026-03-05T02:37:23.091Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:23.072606445Z","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: 180, tv_nsec: 993103306 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1242026-03-05T02:37:23.091Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:23.07271479Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1252026-03-05T02:37:23.091Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:23.076838498Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"7103cd3a3d7b0112d2949dd135db06fef0c156bb"}
1262026-03-05T02:37:23.115Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:23.080591976Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/7103cd3a3d7b0112d2949dd135db06fef0c156bb/crucible-nightly.sha256.txt","timeout":"600s"}
1272026-03-05T02:37:23.385Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:23.365742929Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1282026-03-05T02:37:23.965Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:23.952064259Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/3db8c282441aad15c0e583280d8f9903373bd953/propolis-server.sha256.txt"}
1292026-03-05T02:37:24.131Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.118334698Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1302026-03-05T02:37:24.169Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.118403478Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1312026-03-05T02:37:24.169Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.119328678Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1322026-03-05T02:37:24.169Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.119388611Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1332026-03-05T02:37:24.169Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.119418818Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1342026-03-05T02:37:24.169Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.119449116Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1352026-03-05T02:37:24.169Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.12091603Z","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"}
1362026-03-05T02:37:24.169Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.124397202Z","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"}
1372026-03-05T02:37:24.169Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.125160396Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1382026-03-05T02:37:24.562Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.549586149Z","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"}
1392026-03-05T02:37:24.588Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:24.561910956Z","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"}
1402026-03-05T02:37:31.139Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.124865396Z","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"}
1412026-03-05T02:37:31.166Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.126435465Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1422026-03-05T02:37:31.166Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.141325442Z","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"}
1432026-03-05T02:37:31.166Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.141536521Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-0cffc959-9d39-42b1-81fa-2246927417b1\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1442026-03-05T02:37:31.192Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.167168662Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-0cffc959-9d39-42b1-81fa-2246927417b1\", \"phd-artifacts/phd-clone-3a6f5b69-38e0-447f-8c47-b3c76ac8fc17\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1452026-03-05T02:37:31.218Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.186223665Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-3a6f5b69-38e0-447f-8c47-b3c76ac8fc17\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1462026-03-05T02:37:31.218Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.197042664Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-3a6f5b69-38e0-447f-8c47-b3c76ac8fc17 0B 25.3T 48.9M /phd-artifacts/phd-clone-3a6f5b69-38e0-447f-8c47-b3c76ac8fc17\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1472026-03-05T02:37:31.218Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.200338777Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1482026-03-05T02:37:31.218Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.200449586Z","target":"phd_framework::test_vm","line":318,"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"}
1492026-03-05T02:37:31.218Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.200520981Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/24618169e665cc5424f92ba670233c77f4986cf3c1d58ced63b03632f4fdb240/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1502026-03-05T02:37:31.218Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:31.200586185Z","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/3db8c282441aad15c0e583280d8f9903373bd953/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1512026-03-05T02:37:40.424Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:40.339140585Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/24618169e665cc5424f92ba670233c77f4986cf3c1d58ced63b03632f4fdb240/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1522026-03-05T02:37:40.424Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:40.339229994Z","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"}
1532026-03-05T02:37:57.523Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:57.45690419Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/24618169e665cc5424f92ba670233c77f4986cf3c1d58ced63b03632f4fdb240/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"}
1542026-03-05T02:37:57.523Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:57.457034817Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1552026-03-05T02:37:57.576Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 828","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:57.547510679Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1562026-03-05T02:37:57.606Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:57.56139247Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1572026-03-05T02:37:57.606Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:57.569078043Z","target":"phd_framework::test_vm","line":452,"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","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1582026-03-05T02:37:57.606Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:57.571000469Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":26370,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1592026-03-05T02:37:58.148Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.132314959Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1602026-03-05T02:37:58.205Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.135164407Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 4cf3fe77-0ea0-4451-bb9d-672f260107bb, name: \"phd-vm-4cf3fe77-0ea0-4451-bb9d-672f260107bb\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 88bc25c6-a04b-4f19-a820-1426fc42a96b, project_id: 7abdd4f4-922c-440f-bb2c-7ab615f4243c, sled_id: fb9561f5-4f6f-4d9a-a30f-b2d4aaf54dc3, sled_serial: \"fb9561f5-4f6f-4d9a-a30f-b2d4aaf54dc3\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1612026-03-05T02:37:58.205Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.135323659Z","target":"phd_framework::test_vm","line":572,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1622026-03-05T02:37:58.206Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.135379775Z","target":"phd_framework::test_vm","line":577,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632026-03-05T02:37:58.206Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.13682647Z","target":"phd_framework::test_vm","line":572,"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":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
1642026-03-05T02:37:58.206Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.136945696Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-03-05T02:37:58.206Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.137044182Z","target":"phd_framework::test_vm","line":836,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1662026-03-05T02:37:58.206Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.137096Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1672026-03-05T02:37:58.206Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.137148299Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1682026-03-05T02:37:58.206Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:37:58.13721244Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1692026-03-05T02:38:02.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.671682416Z","target":"phd_framework::test_vm","line":902,"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":4534,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
1702026-03-05T02:38:02.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.671771444Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1712026-03-05T02:38:02.716Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.67202824Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1722026-03-05T02:38:02.716Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.672078735Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1732026-03-05T02:38:02.717Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.672119322Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1742026-03-05T02:38:02.717Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.688759809Z","target":"phd_framework::test_vm","line":902,"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":16,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
1752026-03-05T02:38:02.717Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.688857805Z","target":"phd_framework::test_vm","line":844,"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"}
1762026-03-05T02:38:02.717Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.689040991Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1772026-03-05T02:38:02.717Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.689093581Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1782026-03-05T02:38:02.717Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.689131512Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1792026-03-05T02:38:02.755Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.721551308Z","target":"phd_framework::test_vm","line":902,"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":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
1802026-03-05T02:38:02.755Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.721684641Z","target":"phd_framework::test_vm","line":884,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1812026-03-05T02:38:02.755Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.721770513Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4584,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1822026-03-05T02:38:02.755Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.723395426Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1832026-03-05T02:38:02.755Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.723466801Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1842026-03-05T02:38:02.755Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.732439308Z","target":"phd_framework::test_vm","line":902,"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":8,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
1852026-03-05T02:38:02.755Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.732684391Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1862026-03-05T02:38:02.755Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.732774882Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1872026-03-05T02:38:02.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.755974794Z","target":"phd_framework::test_vm","line":902,"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":23,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
1882026-03-05T02:38:02.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.756338541Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1892026-03-05T02:38:02.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.756439172Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1902026-03-05T02:38:02.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.766966291Z","target":"phd_framework::test_vm","line":902,"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":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
1912026-03-05T02:38:02.785Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.767231272Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1922026-03-05T02:38:02.786Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.767318256Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1932026-03-05T02:38:02.815Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.800659405Z","target":"phd_framework::test_vm","line":902,"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":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
1942026-03-05T02:38:02.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.801001011Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1952026-03-05T02:38:02.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.801116018Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1962026-03-05T02:38:02.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.812862952Z","target":"phd_framework::test_vm","line":902,"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":11,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
1972026-03-05T02:38:02.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.813172397Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1982026-03-05T02:38:02.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.813260213Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1992026-03-05T02:38:02.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.845006706Z","target":"phd_framework::test_vm","line":902,"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":31,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
2002026-03-05T02:38:02.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.845259003Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2012026-03-05T02:38:02.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.84531014Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2022026-03-05T02:38:02.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.855901909Z","target":"phd_framework::test_vm","line":902,"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":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
2032026-03-05T02:38:02.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.856164525Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2042026-03-05T02:38:02.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.856264404Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2052026-03-05T02:38:02.912Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.889479797Z","target":"phd_framework::test_vm","line":902,"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":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
2062026-03-05T02:38:02.912Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.889821804Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2072026-03-05T02:38:02.912Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.889924999Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2082026-03-05T02:38:02.941Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.900638358Z","target":"phd_framework::test_vm","line":902,"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":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
2092026-03-05T02:38:02.941Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.900881838Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2102026-03-05T02:38:02.942Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.900979343Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2112026-03-05T02:38:02.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.932963525Z","target":"phd_framework::test_vm","line":902,"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":31,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
2122026-03-05T02:38:02.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.933206234Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2132026-03-05T02:38:02.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.933301915Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2142026-03-05T02:38:02.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.943829643Z","target":"phd_framework::test_vm","line":902,"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":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
2152026-03-05T02:38:02.978Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.944059908Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2162026-03-05T02:38:02.978Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.944153976Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2172026-03-05T02:38:03.010Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.966990731Z","target":"phd_framework::test_vm","line":902,"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":22,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
2182026-03-05T02:38:03.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.967220495Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2192026-03-05T02:38:03.010Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.967346914Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2202026-03-05T02:38:03.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.967427457Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2212026-03-05T02:38:03.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.967895131Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","sha256":"None","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2222026-03-05T02:38:03.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.967953932Z","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"}
2232026-03-05T02:38:03.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.967999558Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2242026-03-05T02:38:03.011Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.9680584Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2252026-03-05T02:38:03.041Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 829","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:02.994627143Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2262026-03-05T02:38:03.041Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:03.008508452Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":41,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2272026-03-05T02:38:03.042Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:03.008589856Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","source":"migration_from_base"}
2282026-03-05T02:38:03.042Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:03.008647916Z","target":"phd_framework::test_vm","line":639,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"eb307271-1717-40d7-9fd5-8e80e98c2293","timeout_duration":"45s","target":"migration_from_base_lifecycle_0","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","source":"migration_from_base"}
2292026-03-05T02:38:03.042Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:03.009151599Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","source":"migration_from_base"}
2302026-03-05T02:38:03.042Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:03.00967059Z","target":"phd_framework::test_vm","line":452,"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","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","source":"migration_from_base"}
2312026-03-05T02:38:03.535Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:03.518262901Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 9acb6ab5-325b-4be9-8194-649aaec79bc0, name: \"phd-vm-9acb6ab5-325b-4be9-8194-649aaec79bc0\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 88bc25c6-a04b-4f19-a820-1426fc42a96b, project_id: 7abdd4f4-922c-440f-bb2c-7ab615f4243c, sled_id: 2ffd9ba2-2bf0-4afe-aafe-72cb54287d39, sled_serial: \"2ffd9ba2-2bf0-4afe-aafe-72cb54287d39\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target":"migration_from_base_lifecycle_0","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","source":"migration_from_base"}
2322026-03-05T02:38:03.568Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:03.519041934Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base","migration_id":"eb307271-1717-40d7-9fd5-8e80e98c2293","source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","source":"migration_from_base"}
2332026-03-05T02:38:08.445Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.215777214Z","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}}"}
2342026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.640805382Z","target":"phd_framework::test_vm","line":673,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","source":"migration_from_base"}
2352026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.64093647Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base","migration_id":"eb307271-1717-40d7-9fd5-8e80e98c2293","source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","elapsed_milliseconds":3121,"source":"migration_from_base"}
2362026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.643193558Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2372026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.644673627Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2382026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.644732969Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2392026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.646056242Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base","vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2402026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.725062185Z","target":"phd_framework::test_vm","line":1152,"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":80,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
2412026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.725237626Z","target":"phd_framework::test_vm","line":409,"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":9163,"vm_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb"}
2422026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.725343477Z","target":"phd_framework::test_vm","line":902,"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":80,"vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0"}
2432026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.725544537Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2442026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.725605622Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2452026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.755417397Z","target":"phd_framework::test_vm","line":902,"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":29,"vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0"}
2462026-03-05T02:38:08.515Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.755609911Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2472026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.755816792Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2482026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.755933292Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8623}
2492026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.756021309Z","target":"phd_runner::execute","line":130,"file":"phd-tests/runner/src/execute.rs"}
2502026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.756176372Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2512026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:06.756957198Z","target":"phd_framework::test_vm","line":1175,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2522026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.166647635Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.254444151Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.254537557Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-3a6f5b69-38e0-447f-8c47-b3c76ac8fc17\"]","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.27984818Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.279955283Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-0cffc959-9d39-42b1-81fa-2246927417b1\"]","verb":"destroy","vm":"migration_from_base_lifecycle_0","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2572026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.299164748Z","target":"phd_framework::test_vm","line":1152,"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":543,"vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0"}
2582026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.299973046Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","elapsed_milliseconds":4290,"source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","vm_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0"}
2592026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300023131Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":543}
2602026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300039302Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","target_id":"9acb6ab5-325b-4be9-8194-649aaec79bc0","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4291,"source_id":"4cf3fe77-0ea0-4451-bb9d-672f260107bb","source":"migration_from_base"}
2612026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300085749Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":43178,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2622026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300099295Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
2632026-03-05T02:38:08.516Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300146755Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2642026-03-05T02:38:08.517Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300195868Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2652026-03-05T02:38:08.517Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300355049Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2662026-03-05T02:38:08.517Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300448846Z","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"}
2672026-03-05T02:38:08.517Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300511424Z","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"}
2682026-03-05T02:38:08.517Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300574614Z","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"}
2692026-03-05T02:38:08.517Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.300641841Z","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"}
2702026-03-05T02:38:08.517Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.310927191Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 880M 25.3T 879M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2712026-03-05T02:38:08.517Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.311080591Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-7b23b351-d63a-400b-9fcd-b590babe1407\"]","path":"phd_tests::migrate::from_base::serial_history"}
2722026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.331919006Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-7b23b351-d63a-400b-9fcd-b590babe1407\", \"phd-artifacts/phd-clone-a9032faa-c2a2-444a-adf9-7931d585a94b\"]","path":"phd_tests::migrate::from_base::serial_history"}
2732026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.350200489Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-a9032faa-c2a2-444a-adf9-7931d585a94b\"]","path":"phd_tests::migrate::from_base::serial_history"}
2742026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.361676861Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-a9032faa-c2a2-444a-adf9-7931d585a94b 0B 25.3T 879M /phd-artifacts/phd-clone-a9032faa-c2a2-444a-adf9-7931d585a94b\n","path":"phd_tests::migrate::from_base::serial_history"}
2752026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.362370823Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2762026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.362434754Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
2772026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.362511649Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/24618169e665cc5424f92ba670233c77f4986cf3c1d58ced63b03632f4fdb240/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2782026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.362578476Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/24618169e665cc5424f92ba670233c77f4986cf3c1d58ced63b03632f4fdb240/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
2792026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.362652416Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2802026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 838","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.390341245Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
2812026-03-05T02:38:08.518Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.404974006Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":42,"path":"phd_tests::migrate::from_base::serial_history"}
2822026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.405087571Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2832026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.405801Z","target":"phd_framework::test_vm","line":452,"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":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2842026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.854255059Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2852026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.85520204Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 09d62bfe-18e8-4c6e-9e37-bfa581df32db, name: \"phd-vm-09d62bfe-18e8-4c6e-9e37-bfa581df32db\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: adf011b1-9240-4bf3-a2a1-cf4b66d35e39, project_id: 9ca8d271-1764-4695-a6b0-5bdea104fd6d, sled_id: 49547da9-586d-4cbf-85b0-54fdb10f6efa, sled_serial: \"49547da9-586d-4cbf-85b0-54fdb10f6efa\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2862026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.855333428Z","target":"phd_framework::test_vm","line":572,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2872026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.855382671Z","target":"phd_framework::test_vm","line":577,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2882026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.856365049Z","target":"phd_framework::test_vm","line":572,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":0,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
2892026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.856438448Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2902026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.856490636Z","target":"phd_framework::test_vm","line":836,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","timeout_duration":"300s","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","path":"phd_tests::migrate::from_base::serial_history"}
2912026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.856544047Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
2922026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.856585376Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2932026-03-05T02:38:08.519Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:07.856643375Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2942026-03-05T02:38:12.449Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.433664073Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4577,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
2952026-03-05T02:38:12.449Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.433755667Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
2962026-03-05T02:38:12.449Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.433946027Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
2972026-03-05T02:38:12.450Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.433998656Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2982026-03-05T02:38:12.450Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.434039944Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2992026-03-05T02:38:12.474Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.451806431Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":17,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
3002026-03-05T02:38:12.475Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.451899868Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3012026-03-05T02:38:12.475Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.452099315Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3022026-03-05T02:38:12.475Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.452156693Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3032026-03-05T02:38:12.475Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.452204363Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3042026-03-05T02:38:12.502Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.485285971Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":33,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
3052026-03-05T02:38:12.502Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.485441144Z","target":"phd_framework::test_vm","line":884,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3062026-03-05T02:38:12.502Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.485512289Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4629,"path":"phd_tests::migrate::from_base::serial_history"}
3072026-03-05T02:38:12.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.48577207Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3082026-03-05T02:38:12.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.485846411Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3092026-03-05T02:38:12.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.496316382Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":10,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
3102026-03-05T02:38:12.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.496575772Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3112026-03-05T02:38:12.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.496670411Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3122026-03-05T02:38:12.551Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.528782616Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":32,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
3132026-03-05T02:38:12.551Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.529095577Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3142026-03-05T02:38:12.551Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.529198953Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3152026-03-05T02:38:12.576Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.539796523Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":10,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
3162026-03-05T02:38:12.576Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.540020757Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3172026-03-05T02:38:12.576Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.540113342Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3182026-03-05T02:38:12.601Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.573044064Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":32,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
3192026-03-05T02:38:12.601Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.57842499Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3202026-03-05T02:38:12.601Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.57854668Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3212026-03-05T02:38:12.601Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.578598087Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3222026-03-05T02:38:12.602Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.578664312Z","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"}
3232026-03-05T02:38:12.602Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.578713896Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::serial_history"}
3242026-03-05T02:38:12.603Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.57879549Z","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"}
3252026-03-05T02:38:12.627Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 839","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.604634484Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
3262026-03-05T02:38:12.652Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.618077515Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":39,"path":"phd_tests::migrate::from_base::serial_history"}
3272026-03-05T02:38:12.652Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.618156184Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","path":"phd_tests::migrate::from_base::serial_history","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0"}
3282026-03-05T02:38:12.652Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.618219724Z","target":"phd_framework::test_vm","line":639,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"76890be8-21b1-4529-aa35-76d51baa46b4","source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","path":"phd_tests::migrate::from_base::serial_history","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0"}
3292026-03-05T02:38:12.652Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.618294355Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7"}
3302026-03-05T02:38:12.652Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:12.618887216Z","target":"phd_framework::test_vm","line":452,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7"}
3312026-03-05T02:38:13.275Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:13.259595952Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 199dfb4e-861e-41ae-8060-2fed381732b7, name: \"phd-vm-199dfb4e-861e-41ae-8060-2fed381732b7\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: adf011b1-9240-4bf3-a2a1-cf4b66d35e39, project_id: 9ca8d271-1764-4695-a6b0-5bdea104fd6d, sled_id: 1d7e25b8-8d09-4552-a46b-019223a3540f, sled_serial: \"1d7e25b8-8d09-4552-a46b-019223a3540f\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7"}
3322026-03-05T02:38:13.275Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:13.259776674Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","path":"phd_tests::migrate::from_base::serial_history","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","migration_id":"76890be8-21b1-4529-aa35-76d51baa46b4"}
3332026-03-05T02:38:15.996Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:15.980461702Z","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}}"}
3342026-03-05T02:38:16.021Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.005732659Z","target":"phd_framework::test_vm","line":673,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","path":"phd_tests::migrate::from_base::serial_history","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0"}
3352026-03-05T02:38:16.021Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.005796981Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","elapsed_milliseconds":2745,"path":"phd_tests::migrate::from_base::serial_history","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","migration_id":"76890be8-21b1-4529-aa35-76d51baa46b4"}
3362026-03-05T02:38:16.047Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.008041105Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3372026-03-05T02:38:16.047Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.009842912Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3382026-03-05T02:38:16.107Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.091285162Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":82,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
3392026-03-05T02:38:16.131Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.091455133Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":8686,"vm_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db"}
3402026-03-05T02:38:16.131Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.094422234Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3412026-03-05T02:38:16.131Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.094597746Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3422026-03-05T02:38:16.131Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.094724636Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8240}
3432026-03-05T02:38:16.131Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.094769962Z","target":"phd_runner::execute","line":130,"file":"phd-tests/runner/src/execute.rs"}
3442026-03-05T02:38:16.131Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.094886372Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3452026-03-05T02:38:16.131Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.095926459Z","target":"phd_framework::test_vm","line":1175,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3462026-03-05T02:38:16.807Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.791010161Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3472026-03-05T02:38:16.884Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.868798511Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3482026-03-05T02:38:16.884Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.868925361Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-a9032faa-c2a2-444a-adf9-7931d585a94b\"]","verb":"destroy","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3492026-03-05T02:38:16.910Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.894347545Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3502026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.894436783Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-7b23b351-d63a-400b-9fcd-b590babe1407\"]","verb":"destroy","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3512026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913074137Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":818,"vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7"}
3522026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913291578Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":818}
3532026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913373994Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3542026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913414971Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3552026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913354337Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":4294,"source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"199dfb4e-861e-41ae-8060-2fed381732b7"}
3562026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913452142Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3572026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913463133Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"09d62bfe-18e8-4c6e-9e37-bfa581df32db","path":"phd_tests::migrate::from_base::serial_history","target_id":"199dfb4e-861e-41ae-8060-2fed381732b7","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":4295}
3582026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913524769Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":9613,"path":"phd_tests::migrate::from_base::serial_history"}
3592026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913629066Z","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"}
3602026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913725408Z","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"}
3612026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913788638Z","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"}
3622026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913852749Z","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"}
3632026-03-05T02:38:16.935Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.913916911Z","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"}
3642026-03-05T02:38:16.960Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.925359819Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 880M 25.3T 879M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3652026-03-05T02:38:16.960Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.925475608Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-ad5fa77c-6aae-45d8-a279-a8419f729eed\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3662026-03-05T02:38:16.985Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.947812037Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-ad5fa77c-6aae-45d8-a279-a8419f729eed\", \"phd-artifacts/phd-clone-51245bc2-c9f8-4ede-b854-c03585672bdb\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3672026-03-05T02:38:17.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.973779814Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-51245bc2-c9f8-4ede-b854-c03585672bdb\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3682026-03-05T02:38:17.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.985694424Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-51245bc2-c9f8-4ede-b854-c03585672bdb 0B 25.3T 879M /phd-artifacts/phd-clone-51245bc2-c9f8-4ede-b854-c03585672bdb\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3692026-03-05T02:38:17.010Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.986375893Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3702026-03-05T02:38:17.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.986450193Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3712026-03-05T02:38:17.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.986529984Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/24618169e665cc5424f92ba670233c77f4986cf3c1d58ced63b03632f4fdb240/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3722026-03-05T02:38:17.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.986598924Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/24618169e665cc5424f92ba670233c77f4986cf3c1d58ced63b03632f4fdb240/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3732026-03-05T02:38:17.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:16.986687362Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3742026-03-05T02:38:17.034Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 848","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.018969468Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3752026-03-05T02:38:17.059Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.033456002Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":47,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-03-05T02:38:17.060Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.033564858Z","target":"phd_framework::test_vm","line":409,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3772026-03-05T02:38:17.060Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.034207573Z","target":"phd_framework::test_vm","line":452,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3782026-03-05T02:38:17.729Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.713290557Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3792026-03-05T02:38:17.776Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.714137339Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 5fc8499f-18b0-4b25-a052-e5b3e1d8626b, name: \"phd-vm-5fc8499f-18b0-4b25-a052-e5b3e1d8626b\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0a887aad-9f38-4214-8ef7-a20b42cb86c0, project_id: 8eae840f-247e-417e-861b-679a83d15282, sled_id: 7b811b67-b532-42ac-8393-86881cc157b7, sled_serial: \"7b811b67-b532-42ac-8393-86881cc157b7\", 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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3802026-03-05T02:38:17.776Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.714372183Z","target":"phd_framework::test_vm","line":572,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3812026-03-05T02:38:17.776Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.714429972Z","target":"phd_framework::test_vm","line":577,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3822026-03-05T02:38:17.776Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.715411468Z","target":"phd_framework::test_vm","line":572,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3832026-03-05T02:38:17.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.715494525Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-03-05T02:38:17.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.715550862Z","target":"phd_framework::test_vm","line":836,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-03-05T02:38:17.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.715596358Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3862026-03-05T02:38:17.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.715637125Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3872026-03-05T02:38:17.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:17.715695655Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3882026-03-05T02:38:22.245Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.229165649Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4513,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3892026-03-05T02:38:22.245Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.229257453Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3902026-03-05T02:38:22.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.229504299Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3912026-03-05T02:38:22.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.22955728Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3922026-03-05T02:38:22.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.229597265Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3932026-03-05T02:38:22.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.247176688Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":17,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3942026-03-05T02:38:22.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.247227544Z","target":"phd_framework::test_vm","line":844,"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"}
3952026-03-05T02:38:22.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.247374773Z","target":"phd_framework::test_vm","line":844,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-03-05T02:38:22.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.247418585Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3972026-03-05T02:38:22.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.247459202Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3982026-03-05T02:38:22.296Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.280551039Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
3992026-03-05T02:38:22.296Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.280712364Z","target":"phd_framework::test_vm","line":884,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4002026-03-05T02:38:22.296Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.280784811Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4565,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012026-03-05T02:38:22.322Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.281046757Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4022026-03-05T02:38:22.322Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.281144261Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4032026-03-05T02:38:22.322Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.291641692Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4042026-03-05T02:38:22.322Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.291896554Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4052026-03-05T02:38:22.322Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.292002133Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4062026-03-05T02:38:22.346Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.324945009Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4072026-03-05T02:38:22.346Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.32521511Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4082026-03-05T02:38:22.346Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.325308436Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4092026-03-05T02:38:22.372Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.335799436Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4102026-03-05T02:38:22.372Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.336054278Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4112026-03-05T02:38:22.372Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.336149108Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4122026-03-05T02:38:22.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.369026599Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4132026-03-05T02:38:22.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.369330765Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4142026-03-05T02:38:22.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.369435463Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4152026-03-05T02:38:22.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.379933054Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4162026-03-05T02:38:22.397Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.380223463Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4172026-03-05T02:38:22.397Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.38032778Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4182026-03-05T02:38:22.431Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.413401393Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4192026-03-05T02:38:22.457Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.413724353Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4202026-03-05T02:38:22.457Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.413852586Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4212026-03-05T02:38:22.457Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.424835695Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4222026-03-05T02:38:22.457Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.425118059Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4232026-03-05T02:38:22.457Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.425221024Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4242026-03-05T02:38:22.482Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.457609142Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4252026-03-05T02:38:22.482Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.457932674Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4262026-03-05T02:38:22.482Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.458037281Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4272026-03-05T02:38:22.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.468249573Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4282026-03-05T02:38:22.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.468509484Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4292026-03-05T02:38:22.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.468582382Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4302026-03-05T02:38:22.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.502033368Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4312026-03-05T02:38:22.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.502278993Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4322026-03-05T02:38:22.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.502373832Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4332026-03-05T02:38:22.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.512602695Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4342026-03-05T02:38:22.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.512830726Z","target":"phd_framework::test_vm","line":902,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4352026-03-05T02:38:22.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.512924193Z","target":"phd_framework::test_vm","line":909,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4362026-03-05T02:38:22.561Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.54533887Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4372026-03-05T02:38:22.589Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.546530403Z","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"}
4382026-03-05T02:38:22.589Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.546610344Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4392026-03-05T02:38:22.589Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.546660569Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4402026-03-05T02:38:22.589Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.546727265Z","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"}
4412026-03-05T02:38:22.589Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.546781979Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4422026-03-05T02:38:22.589Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.546860738Z","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"}
4432026-03-05T02:38:22.615Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 849","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.573556171Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4442026-03-05T02:38:22.615Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.587018929Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":40,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4452026-03-05T02:38:22.615Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.587099481Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","target":"migration_from_base_and_back_lifecycle_0","target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4462026-03-05T02:38:22.615Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.587169834Z","target":"phd_framework::test_vm","line":639,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"22b21737-7d35-4f73-900b-01fdf3f2f562","source":"migration_from_base_and_back","source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","target":"migration_from_base_and_back_lifecycle_0","target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4472026-03-05T02:38:22.615Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.587232132Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4482026-03-05T02:38:22.615Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:22.587826927Z","target":"phd_framework::test_vm","line":452,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source":"migration_from_base_and_back","source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4492026-03-05T02:38:23.332Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:23.314669755Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 4d89fe20-8707-470d-a20d-2a5f5ffdbfd9, name: \"phd-vm-4d89fe20-8707-470d-a20d-2a5f5ffdbfd9\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0a887aad-9f38-4214-8ef7-a20b42cb86c0, project_id: 8eae840f-247e-417e-861b-679a83d15282, sled_id: de1b2296-a3a3-44da-9205-85e719c060c3, sled_serial: \"de1b2296-a3a3-44da-9205-85e719c060c3\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back","source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4502026-03-05T02:38:23.332Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:23.314880914Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","target":"migration_from_base_and_back_lifecycle_0","migration_id":"22b21737-7d35-4f73-900b-01fdf3f2f562","target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-03-05T02:38:26.107Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:26.090682188Z","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}}"}
4522026-03-05T02:38:27.220Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.200301488Z","target":"phd_framework::test_vm","line":673,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","target":"migration_from_base_and_back_lifecycle_0","target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-03-05T02:38:27.220Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.2003607Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","target":"migration_from_base_and_back_lifecycle_0","migration_id":"22b21737-7d35-4f73-900b-01fdf3f2f562","target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":3885}
4542026-03-05T02:38:27.245Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.202576601Z","target":"phd_framework::test_vm","line":1152,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4552026-03-05T02:38:27.245Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.202789824Z","target":"phd_framework::test_vm","line":902,"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":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4562026-03-05T02:38:27.245Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.202847813Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4572026-03-05T02:38:27.245Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.20400916Z","target":"phd_framework::test_vm::server","line":140,"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":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4582026-03-05T02:38:27.299Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.282868225Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":80,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4592026-03-05T02:38:27.324Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.283157131Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10249,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b"}
4602026-03-05T02:38:27.324Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.283264384Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":80,"vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4612026-03-05T02:38:27.324Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.283511952Z","target":"phd_framework::test_vm","line":902,"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":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4622026-03-05T02:38:27.324Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.283582355Z","target":"phd_framework::test_vm","line":909,"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":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4632026-03-05T02:38:27.350Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.314612614Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4642026-03-05T02:38:27.350Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.31477982Z","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"}
4652026-03-05T02:38:27.350Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.314910026Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4662026-03-05T02:38:27.350Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.314990438Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_1","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4672026-03-05T02:38:27.350Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.315096429Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/24618169e665cc5424f92ba670233c77f4986cf3c1d58ced63b03632f4fdb240/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4682026-03-05T02:38:27.350Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.315191158Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/24618169e665cc5424f92ba670233c77f4986cf3c1d58ced63b03632f4fdb240/propolis-server\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4692026-03-05T02:38:27.350Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.315332645Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4702026-03-05T02:38:27.376Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 851","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.343432242Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4712026-03-05T02:38:27.376Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.357578923Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":42,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4722026-03-05T02:38:27.376Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.357676318Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","target":"migration_from_base_and_back_lifecycle_1","target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4732026-03-05T02:38:27.376Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.357748404Z","target":"phd_framework::test_vm","line":639,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"ae147162-d564-436c-a303-0817346b57de","timeout_duration":"45s","source":"migration_from_base_and_back_lifecycle_0","source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","target":"migration_from_base_and_back_lifecycle_1","target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4742026-03-05T02:38:27.376Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.357821592Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"783fed6d-eca7-492d-a201-5ba92e096707"}
4752026-03-05T02:38:27.376Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:27.358391741Z","target":"phd_framework::test_vm","line":452,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","source":"migration_from_base_and_back_lifecycle_0","source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"783fed6d-eca7-492d-a201-5ba92e096707"}
4762026-03-05T02:38:28.218Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:28.201572709Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 783fed6d-eca7-492d-a201-5ba92e096707, name: \"phd-vm-783fed6d-eca7-492d-a201-5ba92e096707\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0a887aad-9f38-4214-8ef7-a20b42cb86c0, project_id: 8eae840f-247e-417e-861b-679a83d15282, sled_id: a5e35e07-71a9-4b3b-a8e4-60ab886b6f07, sled_serial: \"a5e35e07-71a9-4b3b-a8e4-60ab886b6f07\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_0","source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"783fed6d-eca7-492d-a201-5ba92e096707"}
4772026-03-05T02:38:28.218Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:28.201783107Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","target":"migration_from_base_and_back_lifecycle_1","migration_id":"ae147162-d564-436c-a303-0817346b57de","target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-03-05T02:38:30.915Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:30.897483226Z","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}}"}
4792026-03-05T02:38:32.968Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:32.951585819Z","target":"phd_framework::test_vm","line":673,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","target":"migration_from_base_and_back_lifecycle_1","target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-03-05T02:38:32.968Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:32.951663556Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","target":"migration_from_base_and_back_lifecycle_1","migration_id":"ae147162-d564-436c-a303-0817346b57de","target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4749}
4812026-03-05T02:38:32.993Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:32.953925784Z","target":"phd_framework::test_vm","line":1152,"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":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4822026-03-05T02:38:32.993Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:32.954120672Z","target":"phd_framework::test_vm","line":902,"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":"783fed6d-eca7-492d-a201-5ba92e096707"}
4832026-03-05T02:38:32.993Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:32.954175797Z","target":"phd_framework::test_vm","line":909,"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":"783fed6d-eca7-492d-a201-5ba92e096707"}
4842026-03-05T02:38:32.993Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:32.956013341Z","target":"phd_framework::test_vm::server","line":140,"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":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4852026-03-05T02:38:33.051Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.033828342Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":79,"vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9"}
4862026-03-05T02:38:33.077Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.034145251Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","vm_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","elapsed_milliseconds":10446,"source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","vm":"migration_from_base_and_back_lifecycle_0","target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4872026-03-05T02:38:33.077Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.034292409Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"5fc8499f-18b0-4b25-a052-e5b3e1d8626b","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":10447,"target_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4882026-03-05T02:38:33.077Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.034337254Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":80,"vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"783fed6d-eca7-492d-a201-5ba92e096707"}
4892026-03-05T02:38:33.077Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.034533054Z","target":"phd_framework::test_vm","line":902,"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":"783fed6d-eca7-492d-a201-5ba92e096707"}
4902026-03-05T02:38:33.077Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.034596725Z","target":"phd_framework::test_vm","line":909,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"783fed6d-eca7-492d-a201-5ba92e096707"}
4912026-03-05T02:38:33.102Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.065233359Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":30,"vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"783fed6d-eca7-492d-a201-5ba92e096707"}
4922026-03-05T02:38:33.102Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.065354198Z","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"}
4932026-03-05T02:38:33.102Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.065592679Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4942026-03-05T02:38:33.102Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.065674934Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_2","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4952026-03-05T02:38:33.102Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.065783319Z","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"}
4962026-03-05T02:38:33.102Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.065871275Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9006","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4972026-03-05T02:38:33.102Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.06598474Z","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"}
4982026-03-05T02:38:33.127Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 853","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.093675195Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4992026-03-05T02:38:33.127Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.108060347Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":42,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5002026-03-05T02:38:33.127Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.108163913Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"783fed6d-eca7-492d-a201-5ba92e096707","target":"migration_from_base_and_back_lifecycle_2","target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5012026-03-05T02:38:33.127Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.108250878Z","target":"phd_framework::test_vm","line":639,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"a238c3c6-79cf-486c-80e1-5da1b9e2c180","timeout_duration":"45s","source":"migration_from_base_and_back_lifecycle_1","source_id":"783fed6d-eca7-492d-a201-5ba92e096707","target":"migration_from_base_and_back_lifecycle_2","target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5022026-03-05T02:38:33.127Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.108325749Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"783fed6d-eca7-492d-a201-5ba92e096707","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5032026-03-05T02:38:33.127Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.108993241Z","target":"phd_framework::test_vm","line":452,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","source":"migration_from_base_and_back_lifecycle_1","source_id":"783fed6d-eca7-492d-a201-5ba92e096707","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5042026-03-05T02:38:33.638Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.62144471Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 3bedbe69-133a-480b-8d57-cba4356ff9d3, name: \"phd-vm-3bedbe69-133a-480b-8d57-cba4356ff9d3\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0a887aad-9f38-4214-8ef7-a20b42cb86c0, project_id: 8eae840f-247e-417e-861b-679a83d15282, sled_id: 7c871e32-1503-415e-a348-4fc321df53e9, sled_serial: \"7c871e32-1503-415e-a348-4fc321df53e9\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_1","source_id":"783fed6d-eca7-492d-a201-5ba92e096707","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5052026-03-05T02:38:33.638Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:33.621621013Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"783fed6d-eca7-492d-a201-5ba92e096707","target":"migration_from_base_and_back_lifecycle_2","migration_id":"a238c3c6-79cf-486c-80e1-5da1b9e2c180","target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-03-05T02:38:36.316Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:36.299266513Z","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}}"}
5072026-03-05T02:38:37.608Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.590260416Z","target":"phd_framework::test_vm","line":673,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"783fed6d-eca7-492d-a201-5ba92e096707","target":"migration_from_base_and_back_lifecycle_2","target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-03-05T02:38:37.608Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.59033625Z","target":"phd_framework::test_vm","line":660,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"783fed6d-eca7-492d-a201-5ba92e096707","target":"migration_from_base_and_back_lifecycle_2","migration_id":"a238c3c6-79cf-486c-80e1-5da1b9e2c180","target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":3968}
5092026-03-05T02:38:37.633Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.593013011Z","target":"phd_framework::test_vm","line":1152,"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":"783fed6d-eca7-492d-a201-5ba92e096707"}
5102026-03-05T02:38:37.633Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.593301918Z","target":"phd_framework::test_vm","line":902,"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":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5112026-03-05T02:38:37.633Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.593367111Z","target":"phd_framework::test_vm","line":909,"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":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5122026-03-05T02:38:37.633Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.59493737Z","target":"phd_framework::test_vm::server","line":140,"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":"783fed6d-eca7-492d-a201-5ba92e096707"}
5132026-03-05T02:38:37.691Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.674634791Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":81,"vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"783fed6d-eca7-492d-a201-5ba92e096707"}
5142026-03-05T02:38:37.717Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.674932824Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","vm_id":"783fed6d-eca7-492d-a201-5ba92e096707","elapsed_milliseconds":10317,"source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","vm":"migration_from_base_and_back_lifecycle_1","target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5152026-03-05T02:38:37.717Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.675049635Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"4d89fe20-8707-470d-a20d-2a5f5ffdbfd9","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":10317,"target_id":"783fed6d-eca7-492d-a201-5ba92e096707","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5162026-03-05T02:38:37.717Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.675094771Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":81,"vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5172026-03-05T02:38:37.717Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.675299207Z","target":"phd_framework::test_vm","line":902,"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":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5182026-03-05T02:38:37.717Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.675365723Z","target":"phd_framework::test_vm","line":909,"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":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5192026-03-05T02:38:37.744Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.704404666Z","target":"phd_framework::test_vm","line":902,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":29,"vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5202026-03-05T02:38:37.744Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.704579607Z","target":"phd_framework::test_vm","line":1152,"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":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5212026-03-05T02:38:37.744Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.704829559Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5222026-03-05T02:38:37.744Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.705008718Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":19991}
5232026-03-05T02:38:37.744Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.70504122Z","target":"phd_runner::execute","line":130,"file":"phd-tests/runner/src/execute.rs"}
5242026-03-05T02:38:37.744Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.705179732Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5252026-03-05T02:38:37.744Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:37.706607983Z","target":"phd_framework::test_vm","line":1175,"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":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5262026-03-05T02:38:38.192Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.175653289Z","target":"phd_framework::test_vm::server","line":140,"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":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5272026-03-05T02:38:38.265Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.248074931Z","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":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5282026-03-05T02:38:38.265Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.248152808Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-51245bc2-c9f8-4ede-b854-c03585672bdb\"]","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5292026-03-05T02:38:38.292Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.275221866Z","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":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5302026-03-05T02:38:38.292Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.275278453Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-ad5fa77c-6aae-45d8-a279-a8419f729eed\"]","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5312026-03-05T02:38:38.318Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.292772214Z","target":"phd_framework::test_vm","line":1152,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":587,"vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3"}
5322026-03-05T02:38:38.318Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.292977642Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":587}
5332026-03-05T02:38:38.318Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.292975338Z","target":"phd_framework::test_vm","line":409,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","vm_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","elapsed_milliseconds":5184,"source_id":"783fed6d-eca7-492d-a201-5ba92e096707","vm":"migration_from_base_and_back_lifecycle_2","target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5342026-03-05T02:38:38.318Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.293056652Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5352026-03-05T02:38:38.318Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.293074996Z","target":"phd_framework::test_vm","line":606,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"783fed6d-eca7-492d-a201-5ba92e096707","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":5184,"target_id":"3bedbe69-133a-480b-8d57-cba4356ff9d3","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5362026-03-05T02:38:38.318Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.293098891Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5372026-03-05T02:38:38.318Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.293131102Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":21379,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5382026-03-05T02:38:38.318Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 74.17s
5392026-03-05T02:38:38.318Z
5402026-03-05T02:38:38.318Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":823,"time":"2026-03-05T02:38:38.293813513Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5412026-03-05T02:38:38.395Z
5422026-03-05T02:38:38.420Zreal 1:15.440860418
5432026-03-05T02:38:38.420Zuser 39.371033533
5442026-03-05T02:38:38.420Zsys 19.594432476
5452026-03-05T02:38:38.421Ztrap 0.006316383
5462026-03-05T02:38:38.421Ztflt 0.005508726
5472026-03-05T02:38:38.421Zdflt 0.002624322
5482026-03-05T02:38:38.421Zkflt 0.000000000
5492026-03-05T02:38:38.421Zlock 2:59:31.089813056
5502026-03-05T02:38:38.421Zslp 3:58.048575450
5512026-03-05T02:38:38.421Zlat 1.315894695
5522026-03-05T02:38:38.421Zstop 30.605366705
5532026-03-05T02:38:38.421Z+ failcount=0
5542026-03-05T02:38:38.421Z+ set -e
5552026-03-05T02:38:38.421Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5562026-03-05T02:38:38.421ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5572026-03-05T02:38:38.421Za ./ 0K
5582026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5592026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 139K
5602026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5612026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5622026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 146K
5632026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5642026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::serial_history/ 0K
5652026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 141K
5662026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5672026-03-05T02:38:38.421Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5682026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 147K
5692026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5702026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5712026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 140K
5722026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5732026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5742026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 234K
5752026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5762026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 234K
5772026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5782026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 147K
5792026-03-05T02:38:38.422Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5802026-03-05T02:38:38.447Z+ exitcode=0
5812026-03-05T02:38:38.447Z+ '[' 0 -eq 0 ']'
5822026-03-05T02:38:38.447Z+ echo
5832026-03-05T02:38:38.447Z
5842026-03-05T02:38:38.447Z+ echo 'ALL TESTS PASSED'
5852026-03-05T02:38:38.447ZALL TESTS PASSED
5862026-03-05T02:38:38.447Z
5872026-03-05T02:38:38.447Z+ echo
5882026-03-05T02:38:38.447Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5892026-03-05T02:38:38.447Z+ read
5902026-03-05T02:38:38.447Z+ exit 0
5912026-03-05T02:38:38.447Zprocess exited: duration 96888 ms, exit code 0
 
5922026-03-05T02:38:38.527Zfound 2 output files
5932026-03-05T02:38:38.527Zuploading: /tmp/phd-runner.log (184388 bytes)
5942026-03-05T02:38:39.733Zuploaded: /tmp/phd-runner.log
5952026-03-05T02:38:39.733Zuploading: /tmp/phd-tmp-files.tar.gz (105942 bytes)
5962026-03-05T02:38:40.917Zuploaded: /tmp/phd-tmp-files.tar.gz