01M1D0EGZT98QFDXK877DZ67CY: 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: 01M1D0EW4ENCBMGKC5X6Z6JKEZ

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-08-31T23:05:23.740Zjob dependencies complete; ready to run (waiting for 11 m 31 s)
22026-08-31T23:08:51.162Zjob assigned to worker 01M1D141CFWEH80W5QTMQE6GK6 [factory edgar, gimlet/BRM42220060/1103] (queued for 3 m 27 s)
32026-08-31T23:08:51.566Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-08-31T23:08:51.592Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-08-31T23:08:51.592Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-08-31T23:08:51.627Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-08-31T23:08:51.627Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-08-31T23:09:01.992Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-08-31T23:09:01.992Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-08-31T23:09:02.039Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-08-31T23:09:02.064Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-08-31T23:09:13.737Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-08-31T23:09:13.737Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-08-31T23:09:23.482Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-08-31T23:09:23.483Zstarting task 0: "setup"
162026-08-31T23:09:23.507Z++ uname -s
172026-08-31T23:09:23.508Z+ kern=SunOS
182026-08-31T23:09:23.508Z+ build_user=build
192026-08-31T23:09:23.508Z+ build_uid=12345
202026-08-31T23:09:23.508Z+ work_dir=/work
212026-08-31T23:09:23.508Z+ input_dir=/input
222026-08-31T23:09:23.508Z+ [[ 0 == 12345 ]]
232026-08-31T23:09:23.508Z+ case "$kern" in
242026-08-31T23:09:23.508Z+ groupadd -g 12345 build
252026-08-31T23:09:23.532Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-08-31T23:09:25.519Z+ zfs create -o mountpoint=/work rpool/work
272026-08-31T23:09:25.751Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-08-31T23:09:25.775Z+ home_fs=
292026-08-31T23:09:25.775Z+ [[ '' == autofs ]]
302026-08-31T23:09:25.775Z+ mkdir -p /home/build
312026-08-31T23:09:25.775Z+ chown build:build /home/build /work
322026-08-31T23:09:27.764Z+ chmod 0700 /home/build /work
332026-08-31T23:09:27.788Zprocess exited: duration 4285 ms, exit code 0
 
342026-08-31T23:09:27.837Zstarting task 1: "authentication"
352026-08-31T23:09:27.906Zprocess exited: duration 68 ms, exit code 0
 
362026-08-31T23:09:27.954Zstarting task 2: "build"
372026-08-31T23:09:27.980Z+ indir=/input
382026-08-31T23:09:27.981Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-08-31T23:09:27.981Z+ phddir=/work/phd-test
402026-08-31T23:09:27.981Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-08-31T23:09:28.005Z++ pilot local disk list -H -o type,disk
422026-08-31T23:09:28.005Z++ grep -v M.2
432026-08-31T23:09:28.005Z++ cut -f 2
442026-08-31T23:09:28.055Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC586d0 c9t0014EE81000BC57Cd0 c10t0014EE81000BC3CCd0 c11t0014EE81000BC478d0 c4t0014EE81000BC5BBd0 c3t0014EE81000BC247d0 c2t0014EE81000BC649d0 c6t0014EE81000BC634d0 c5t0014EE81000BC0B1d0
452026-08-31T23:09:30.575Z+ artifactdir=/phd-artifacts
462026-08-31T23:09:30.575Z+ banner Inputs
472026-08-31T23:09:30.599Z ###
482026-08-31T23:09:30.600Z # # # ##### # # ##### ####
492026-08-31T23:09:30.600Z # ## # # # # # # #
502026-08-31T23:09:30.600Z # # # # # # # # # ####
512026-08-31T23:09:30.600Z # # # # ##### # # # #
522026-08-31T23:09:30.600Z # # ## # # # # # #
532026-08-31T23:09:30.600Z ### # # # #### # ####
542026-08-31T23:09:30.600Z
552026-08-31T23:09:30.600Z+ find /input -ls
562026-08-31T23:09:30.600Z 34 1 drwxr-xr-x 3 root root 3 Aug 31 23:08 /input
572026-08-31T23:09:30.600Z 2 1 drwxr-xr-x 3 root root 3 Aug 31 23:08 /input/phd-build
582026-08-31T23:09:30.600Z 3 2 drwxr-xr-x 2 root root 8 Aug 31 23:09 /input/phd-build/out
592026-08-31T23:09:30.600Z 512 219417 -rw-r--r-- 1 root root 224611535 Aug 31 23:09 /input/phd-build/out/propolis-tests-debug.tar.gz
602026-08-31T23:09:30.600Z 128 2 -rw-r--r-- 1 root root 2573 Aug 31 23:08 /input/phd-build/out/phd-run-with-args.sh
612026-08-31T23:09:30.600Z 129 1 -rw-r--r-- 1 root root 65 Aug 31 23:08 /input/phd-build/out/phd-runner.sha256.txt
622026-08-31T23:09:30.600Z 384 261495 -rw-r--r-- 1 root root 267707024 Aug 31 23:09 /input/phd-build/out/propolis-server-debug.tar.gz
632026-08-31T23:09:30.600Z 256 1 -rw-r--r-- 1 root root 65 Aug 31 23:09 /input/phd-build/out/propolis-server-debug.sha256.txt
642026-08-31T23:09:30.600Z 130 187779 -rw-r--r-- 1 root root 192188268 Aug 31 23:09 /input/phd-build/out/phd-runner.tar.gz
652026-08-31T23:09:30.600Z+ rm -rf /work/phd-test
662026-08-31T23:09:30.600Z+ mkdir /work/phd-test
672026-08-31T23:09:30.600Z+ for p in $indir/$indir_suffix
682026-08-31T23:09:30.600Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-08-31T23:09:46.594ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-08-31T23:09:46.594Zx phd-runner, 737380912 bytes, 1440198 tape blocks
712026-08-31T23:09:46.594Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-08-31T23:09:46.618Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-08-31T23:09:51.172Z+ for f in $(tar tf "$p")
742026-08-31T23:09:51.172Z+ chmod +x /work/phd-test/phd-runner
752026-08-31T23:09:51.197Z+ for f in $(tar tf "$p")
762026-08-31T23:09:51.197Z+ chmod +x /work/phd-test/artifacts.toml
772026-08-31T23:09:51.197Z+ for p in $indir/$indir_suffix
782026-08-31T23:09:51.197Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-08-31T23:10:09.528ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-08-31T23:10:09.528Zx propolis-server, 1073528128 bytes, 2096735 tape blocks
812026-08-31T23:10:09.552Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-08-31T23:10:16.440Z+ for f in $(tar tf "$p")
832026-08-31T23:10:16.440Z+ chmod +x /work/phd-test/propolis-server
842026-08-31T23:10:16.464Z+ for p in $indir/$indir_suffix
852026-08-31T23:10:16.464Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-08-31T23:10:32.890ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-08-31T23:10:32.890Zx target/debug/deps/propolis-2a163edea74e5646, 899214560 bytes, 1756279 tape blocks
882026-08-31T23:10:32.915Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-08-31T23:10:38.544Z+ for f in $(tar tf "$p")
902026-08-31T23:10:38.544Z+ chmod +x /work/phd-test/target/debug/deps/propolis-2a163edea74e5646
912026-08-31T23:10:38.568Z+ ls /work/phd-test
922026-08-31T23:10:38.568Zartifacts.toml
932026-08-31T23:10:38.568Zphd-runner
942026-08-31T23:10:38.568Zpropolis-server
952026-08-31T23:10:38.568Ztarget
962026-08-31T23:10:38.568Z+ banner Setup
972026-08-31T23:10:38.568Z+ tmpdir=/tmp/propolis-phd
982026-08-31T23:10:38.568Z+ '[' '!' -d /tmp/propolis-phd ']'
992026-08-31T23:10:38.568Z #####
1002026-08-31T23:10:38.568Z# # ###### ##### # # #####
1012026-08-31T23:10:38.568Z# # # # # # #
1022026-08-31T23:10:38.568Z ##### ##### # # # # #
1032026-08-31T23:10:38.569Z+ mkdir /tmp/propolis-phd
1042026-08-31T23:10:38.569Z # # # # # #####
1052026-08-31T23:10:38.569Z# # # # # # #
1062026-08-31T23:10:38.569Z ##### ###### # #### #
1072026-08-31T23:10:38.569Z
1082026-08-31T23:10:38.569Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-08-31T23:10:39.011Z+ banner Tests
1102026-08-31T23:10:39.036Z#######
1112026-08-31T23:10:39.036Z # ###### #### ##### ####
1122026-08-31T23:10:39.036Z # # # # #
1132026-08-31T23:10:39.036Z # ##### #### # ####
1142026-08-31T23:10:39.036Z # # # # #
1152026-08-31T23:10:39.036Z # # # # # # #
1162026-08-31T23:10:39.036Z # ###### #### # ####
1172026-08-31T23:10:39.036Z
1182026-08-31T23:10:39.036Z+ runner=/work/phd-test/phd-runner
1192026-08-31T23:10:39.036Z+ artifacts=/work/phd-test/artifacts.toml
1202026-08-31T23:10:39.036Z+ propolis=/work/phd-test/propolis-server
1212026-08-31T23:10:39.036Z+ ls /work/phd-test/phd-runner
1222026-08-31T23:10:39.036Z/work/phd-test/phd-runner
1232026-08-31T23:10:39.036Z+ ls /work/phd-test/artifacts.toml
1242026-08-31T23:10:39.036Z/work/phd-test/artifacts.toml
1252026-08-31T23:10:39.036Z+ ls /work/phd-test/propolis-server
1262026-08-31T23:10:39.036Z/work/phd-test/propolis-server
1272026-08-31T23:10:39.036Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-08-31T23:10:39.036Z+ set +e
1292026-08-31T23:10:39.036Z+ RUST_BACKTRACE=1
1302026-08-31T23:10:39.036Z+ RUST_LOG=info,phd=debug
1312026-08-31T23:10:39.036Z+ ptime -m pfexec /work/phd-test/phd-runner --emit-bunyan run --propolis-server-cmd /work/phd-test/propolis-server --crucible-downstairs-commit auto --artifact-toml-path /work/phd-test/artifacts.toml --tmp-directory /tmp/propolis-phd --artifact-directory /phd-artifacts --include-filter phd_tests::migrate::from_base --base-propolis-branch master
1322026-08-31T23:10:39.036Z+ tee /tmp/phd-runner.log
1332026-08-31T23:10:39.226Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:39.197862814Z","target":"phd_runner","line":36,"file":"phd-tests/runner/src/main.rs","runner_args":"ProcessArgs { command: Run(RunOptions { propolis_server_cmd: \"/work/phd-test/propolis-server\", base_propolis_branch: Some(\"master\"), base_propolis_commit: None, base_propolis_cmd: None, crucible_downstairs_cmd: None, crucible_downstairs_commit: Some(Auto), tmp_directory: \"/tmp/propolis-phd\", artifact_directory: Some(\"/phd-artifacts\"), output_mode: TmpFile, default_guest_cpus: 2, default_guest_memory_mib: 512, artifact_toml_path: \"/work/phd-test/artifacts.toml\", default_guest_artifact: \"alpine\", default_bootrom_artifact: \"ovmf\", include_filter: [\"phd_tests::migrate::from_base\"], exclude_filter: [], max_buildomat_wait_secs: 1200, manual_stop_on_failure: false }), disable_ansi: false, emit_bunyan: true }"}
1342026-08-31T23:10:39.250Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:39.221864174Z","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: 261, tv_nsec: 216042043 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-08-31T23:10:39.250Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:39.222455763Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-08-31T23:10:39.250Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:39.224219456Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"ad8a31742adc45e925e63443a5b43c8e30604022"}
1372026-08-31T23:10:39.274Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:39.229293819Z","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/ad8a31742adc45e925e63443a5b43c8e30604022/crucible-nightly.sha256.txt","timeout":"600s"}
1382026-08-31T23:10:39.490Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:39.467753081Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-08-31T23:10:40.011Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:39.988346355Z","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/c9bae7e62e8ae91cae4564397b46a43e7f8ad7f3/propolis-server.sha256.txt","timeout":"600s"}
1402026-08-31T23:10:40.177Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.155168671Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-08-31T23:10:40.201Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.155247771Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-08-31T23:10:40.201Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.15882863Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-08-31T23:10:40.201Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.159653118Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-08-31T23:10:40.201Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.159689727Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-08-31T23:10:40.202Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.159724563Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-08-31T23:10:40.202Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.161169765Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
1472026-08-31T23:10:40.202Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.1632622Z","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::serial_history"}
1482026-08-31T23:10:40.202Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.16533575Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
1492026-08-31T23:10:40.668Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.645603005Z","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::serial_history"}
1502026-08-31T23:10:40.692Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:40.657777429Z","target":"phd_framework::artifacts::store","line":614,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::serial_history"}
1512026-08-31T23:10:47.569Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.546850719Z","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"}
1522026-08-31T23:10:47.594Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.54761283Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::serial_history"}
1532026-08-31T23:10:47.618Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.572803208Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 5.83M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
1542026-08-31T23:10:47.618Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.575797528Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-45aca7b3-7c51-4182-8d68-5f9019793202\"]","path":"phd_tests::migrate::from_base::serial_history"}
1552026-08-31T23:10:47.642Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.597974239Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-45aca7b3-7c51-4182-8d68-5f9019793202\", \"phd-artifacts/phd-clone-40361917-5850-42ef-af94-32a2d8ad997a\"]","path":"phd_tests::migrate::from_base::serial_history"}
1562026-08-31T23:10:47.642Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.61613585Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-40361917-5850-42ef-af94-32a2d8ad997a\"]","path":"phd_tests::migrate::from_base::serial_history"}
1572026-08-31T23:10:47.666Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.626866434Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-40361917-5850-42ef-af94-32a2d8ad997a 0B 25.3T 49.0M /phd-artifacts/phd-clone-40361917-5850-42ef-af94-32a2d8ad997a\n","path":"phd_tests::migrate::from_base::serial_history"}
1582026-08-31T23:10:47.666Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.631684091Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1592026-08-31T23:10:47.666Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.631860585Z","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: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1602026-08-31T23:10:47.667Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.631947589Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/3c6bde1a08b3295d5b61675c8c8fffe6ff15bbfcc9c92a5e8ac0585e74d6b7c0/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1612026-08-31T23:10:47.667Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:10:47.632030045Z","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/c9bae7e62e8ae91cae4564397b46a43e7f8ad7f3/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::serial_history"}
1622026-08-31T23:11:05.532Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:05.511660882Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/3c6bde1a08b3295d5b61675c8c8fffe6ff15bbfcc9c92a5e8ac0585e74d6b7c0/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
1632026-08-31T23:11:05.532Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:05.511745722Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::serial_history"}
1642026-08-31T23:11:30.094Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:30.076938631Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/3c6bde1a08b3295d5b61675c8c8fffe6ff15bbfcc9c92a5e8ac0585e74d6b7c0/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::serial_history"}
1652026-08-31T23:11:30.095Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:30.077082924Z","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"}
1662026-08-31T23:11:30.258Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 917","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:30.2403612Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
1672026-08-31T23:11:30.282Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:30.256251993Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1682026-08-31T23:11:30.306Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:30.268291797Z","target":"phd_framework::test_vm","line":455,"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":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1692026-08-31T23:11:30.306Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:30.271905458Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":42632,"path":"phd_tests::migrate::from_base::serial_history"}
1702026-08-31T23:11:31.094Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.076332089Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-08-31T23:11:31.140Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.079827602Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 78168752-f849-4079-9f04-9eb484b88221, name: \"phd-vm-78168752-f849-4079-9f04-9eb484b88221\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 88771b30-00ed-4ab0-a0c2-d7b5f7a96348, project_id: 48754bc0-896a-44a4-8cf0-f563b4cc1f9c, sled_id: 9f7e6ed1-05c0-4ab4-8009-6a16957d6216, sled_serial: \"9f7e6ed1-05c0-4ab4-8009-6a16957d6216\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1722026-08-31T23:11:31.140Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.079987414Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1732026-08-31T23:11:31.140Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.080047498Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1742026-08-31T23:11:31.140Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.081517951Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":1,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
1752026-08-31T23:11:31.140Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.081628936Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1762026-08-31T23:11:31.140Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.081692281Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","timeout_duration":"300s","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1772026-08-31T23:11:31.140Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.081743152Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
1782026-08-31T23:11:31.140Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.08178929Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1792026-08-31T23:11:31.140Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:31.081860947Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1802026-08-31T23:11:35.713Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.696733182Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4613,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
1812026-08-31T23:11:35.714Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.6968327Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
1822026-08-31T23:11:35.738Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.700523669Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1832026-08-31T23:11:35.738Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.700578429Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1842026-08-31T23:11:35.738Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.700619466Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1852026-08-31T23:11:35.762Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.726591081Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":25,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
1862026-08-31T23:11:35.762Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.726750713Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
1872026-08-31T23:11:35.762Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.727131182Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1882026-08-31T23:11:35.762Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.727200724Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1892026-08-31T23:11:35.762Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.72726239Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1902026-08-31T23:11:35.786Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.760133405Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":32,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
1912026-08-31T23:11:35.786Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.760260576Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1922026-08-31T23:11:35.786Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.760340276Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4677,"path":"phd_tests::migrate::from_base::serial_history"}
1932026-08-31T23:11:35.786Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.761157581Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1942026-08-31T23:11:35.786Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.761211341Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1952026-08-31T23:11:35.811Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.770644912Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":9,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
1962026-08-31T23:11:35.811Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.770891077Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1972026-08-31T23:11:35.811Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.770970958Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1982026-08-31T23:11:35.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.805179349Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":34,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
1992026-08-31T23:11:35.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.805320957Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2002026-08-31T23:11:35.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.805375189Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2012026-08-31T23:11:35.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.816015018Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":10,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
2022026-08-31T23:11:35.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.816260753Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2032026-08-31T23:11:35.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.816408813Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2042026-08-31T23:11:35.866Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.849234009Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":32,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
2052026-08-31T23:11:35.890Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.86057306Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_serial_history_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::serial_history"}
2062026-08-31T23:11:35.890Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.860720799Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2072026-08-31T23:11:35.890Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.86077421Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
2082026-08-31T23:11:35.890Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.860860994Z","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::serial_history"}
2092026-08-31T23:11:35.890Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.860924835Z","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::serial_history"}
2102026-08-31T23:11:35.890Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.860980781Z","target":"phd_framework::test_vm::server","line":66,"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"}
2112026-08-31T23:11:35.890Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.861048469Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2122026-08-31T23:11:35.922Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 918","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.90565431Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
2132026-08-31T23:11:35.946Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.918319127Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":57,"path":"phd_tests::migrate::from_base::serial_history"}
2142026-08-31T23:11:35.946Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.918411532Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","source_id":"78168752-f849-4079-9f04-9eb484b88221","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2152026-08-31T23:11:35.946Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.918869167Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"446c0d51-8683-443d-a574-bfbfd0c020af","timeout_duration":"45s","target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","source_id":"78168752-f849-4079-9f04-9eb484b88221","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2162026-08-31T23:11:35.946Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.918938358Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","source_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base_lifecycle_0","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2172026-08-31T23:11:35.946Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:35.919842759Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","source_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base_lifecycle_0","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2182026-08-31T23:11:36.584Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:36.567226132Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: ca65f8fa-275b-49c0-bd5f-6b1caf850a6b, name: \"phd-vm-ca65f8fa-275b-49c0-bd5f-6b1caf850a6b\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 88771b30-00ed-4ab0-a0c2-d7b5f7a96348, project_id: 48754bc0-896a-44a4-8cf0-f563b4cc1f9c, sled_id: a53afbd4-7472-473b-ac92-9c68e2369460, sled_serial: \"a53afbd4-7472-473b-ac92-9c68e2369460\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","source_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base_lifecycle_0","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2192026-08-31T23:11:36.607Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:36.567916096Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","source_id":"78168752-f849-4079-9f04-9eb484b88221","target":"migration_serial_history_base_lifecycle_0","migration_id":"446c0d51-8683-443d-a574-bfbfd0c020af","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2202026-08-31T23:11:39.009Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:38.992334985Z","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}}"}
2212026-08-31T23:11:40.844Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.827763598Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","source_id":"78168752-f849-4079-9f04-9eb484b88221","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2222026-08-31T23:11:40.844Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.827842287Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","source_id":"78168752-f849-4079-9f04-9eb484b88221","elapsed_milliseconds":4259,"target":"migration_serial_history_base_lifecycle_0","migration_id":"446c0d51-8683-443d-a574-bfbfd0c020af","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2232026-08-31T23:11:40.868Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.831815656Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2242026-08-31T23:11:40.868Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.835147262Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2252026-08-31T23:11:40.925Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.909008476Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":75,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
2262026-08-31T23:11:40.949Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.90935083Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":10650,"vm_id":"78168752-f849-4079-9f04-9eb484b88221","vm":"migration_serial_history_base"}
2272026-08-31T23:11:40.949Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.913163288Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2282026-08-31T23:11:40.949Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.913429431Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2292026-08-31T23:11:40.949Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.914078428Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9835}
2302026-08-31T23:11:40.949Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.914887399Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2312026-08-31T23:11:40.949Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.915019349Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2322026-08-31T23:11:40.949Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:40.91508615Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2332026-08-31T23:11:41.507Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.491802712Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2342026-08-31T23:11:41.593Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.577084346Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2352026-08-31T23:11:41.593Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.577193574Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-40361917-5850-42ef-af94-32a2d8ad997a\"]","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2362026-08-31T23:11:41.618Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.602368123Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2372026-08-31T23:11:41.664Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.602460923Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-45aca7b3-7c51-4182-8d68-5f9019793202\"]","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2382026-08-31T23:11:41.664Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.619928272Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":706,"vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","vm":"migration_serial_history_base_lifecycle_0"}
2392026-08-31T23:11:41.664Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.620161252Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","source_id":"78168752-f849-4079-9f04-9eb484b88221","target":"migration_serial_history_base_lifecycle_0","vm_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":5700,"target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","vm":"migration_serial_history_base_lifecycle_0"}
2402026-08-31T23:11:41.664Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.620262313Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"ca65f8fa-275b-49c0-bd5f-6b1caf850a6b","source_id":"78168752-f849-4079-9f04-9eb484b88221","elapsed_milliseconds":5700,"target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2412026-08-31T23:11:41.664Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.620320914Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":61448,"path":"phd_tests::migrate::from_base::serial_history"}
2422026-08-31T23:11:41.664Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.621088916Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":705}
2432026-08-31T23:11:41.664Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.621167564Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2442026-08-31T23:11:41.664Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.621213231Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2452026-08-31T23:11:41.665Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.621253848Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2462026-08-31T23:11:41.665Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.621409472Z","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"}
2472026-08-31T23:11:41.665Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.621519129Z","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::can_migrate_from_base"}
2482026-08-31T23:11:41.665Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.621590063Z","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"}
2492026-08-31T23:11:41.665Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.621669583Z","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"}
2502026-08-31T23:11:41.665Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.621750767Z","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"}
2512026-08-31T23:11:41.689Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.632695914Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2522026-08-31T23:11:41.689Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.632822313Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-83364c0b-f981-42cc-b7fe-89f574d6b48f\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-08-31T23:11:41.689Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.649976711Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-83364c0b-f981-42cc-b7fe-89f574d6b48f\", \"phd-artifacts/phd-clone-bcc30f2a-8f08-4e58-b81b-6b4c707b8839\"]","verb":"clone","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-08-31T23:11:41.689Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.668116866Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-bcc30f2a-8f08-4e58-b81b-6b4c707b8839\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-08-31T23:11:41.714Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.678600092Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-bcc30f2a-8f08-4e58-b81b-6b4c707b8839 0B 25.3T 1.30G /phd-artifacts/phd-clone-bcc30f2a-8f08-4e58-b81b-6b4c707b8839\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-08-31T23:11:41.714Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.679212096Z","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"}
2572026-08-31T23:11:41.714Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.679276362Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2582026-08-31T23:11:41.714Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.679420418Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/3c6bde1a08b3295d5b61675c8c8fffe6ff15bbfcc9c92a5e8ac0585e74d6b7c0/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2592026-08-31T23:11:41.714Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.679488036Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/3c6bde1a08b3295d5b61675c8c8fffe6ff15bbfcc9c92a5e8ac0585e74d6b7c0/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2602026-08-31T23:11:41.714Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.679569941Z","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"}
2612026-08-31T23:11:41.738Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 927","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.720142969Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2622026-08-31T23:11:41.762Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.734149534Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":54,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2632026-08-31T23:11:41.762Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.734291382Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2642026-08-31T23:11:41.762Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:41.734990371Z","target":"phd_framework::test_vm","line":455,"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":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2652026-08-31T23:11:42.500Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.484615238Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2662026-08-31T23:11:42.524Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.485420972Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 5ba2fabd-df78-4f91-a716-16dca677a693, name: \"phd-vm-5ba2fabd-df78-4f91-a716-16dca677a693\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f9d7ac0b-241e-492b-906d-cff95e9deff5, project_id: ae78e5a8-d159-46be-8e24-f7ba48421a05, sled_id: 9d0300d3-e272-43eb-bea0-99300f872825, sled_serial: \"9d0300d3-e272-43eb-bea0-99300f872825\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2672026-08-31T23:11:42.525Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.485623174Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2682026-08-31T23:11:42.525Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.485700881Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2692026-08-31T23:11:42.525Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.486977574Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":1,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2702026-08-31T23:11:42.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.487101328Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2712026-08-31T23:11:42.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.487174987Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-08-31T23:11:42.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.487227026Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2732026-08-31T23:11:42.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.487274265Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2742026-08-31T23:11:42.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:42.487327195Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2752026-08-31T23:11:47.149Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.13281881Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4644,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2762026-08-31T23:11:47.174Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.132917767Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2772026-08-31T23:11:47.174Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.133111944Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2782026-08-31T23:11:47.174Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.133179692Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2792026-08-31T23:11:47.174Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.133237551Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2802026-08-31T23:11:47.174Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.151902759Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2812026-08-31T23:11:47.174Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.152022926Z","target":"phd_framework::test_vm","line":847,"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"}
2822026-08-31T23:11:47.174Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.152346477Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2832026-08-31T23:11:47.174Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.152452127Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2842026-08-31T23:11:47.174Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.152534276Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2852026-08-31T23:11:47.200Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.184734628Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2862026-08-31T23:11:47.200Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.184882918Z","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"}
2872026-08-31T23:11:47.200Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.184932562Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4696,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2882026-08-31T23:11:47.225Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.185112051Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2892026-08-31T23:11:47.225Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.185186713Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2902026-08-31T23:11:47.225Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.195892857Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2912026-08-31T23:11:47.225Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.196159741Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2922026-08-31T23:11:47.225Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.196265241Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2932026-08-31T23:11:47.250Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.229487007Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2942026-08-31T23:11:47.250Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.230204944Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2952026-08-31T23:11:47.250Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.230258786Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2962026-08-31T23:11:47.275Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.240692255Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2972026-08-31T23:11:47.275Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.240933681Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2982026-08-31T23:11:47.275Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.241035493Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2992026-08-31T23:11:47.300Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.274099924Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3002026-08-31T23:11:47.300Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.274417354Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3012026-08-31T23:11:47.300Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.274532833Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3022026-08-31T23:11:47.324Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.285291079Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3032026-08-31T23:11:47.325Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.285681642Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3042026-08-31T23:11:47.325Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.285794956Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3052026-08-31T23:11:47.350Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.318826384Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3062026-08-31T23:11:47.350Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.319082077Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3072026-08-31T23:11:47.350Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.319186325Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3082026-08-31T23:11:47.350Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.329636375Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3092026-08-31T23:11:47.350Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.329887058Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3102026-08-31T23:11:47.350Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.329994472Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3112026-08-31T23:11:47.378Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.363002113Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3122026-08-31T23:11:47.403Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.363304384Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3132026-08-31T23:11:47.403Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.363364077Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3142026-08-31T23:11:47.403Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.37388954Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3152026-08-31T23:11:47.403Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.374134663Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3162026-08-31T23:11:47.403Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.374237989Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3172026-08-31T23:11:47.428Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.407300505Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3182026-08-31T23:11:47.428Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.408868518Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3192026-08-31T23:11:47.428Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.408931647Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3202026-08-31T23:11:47.453Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.418169736Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3212026-08-31T23:11:47.453Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.418408798Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3222026-08-31T23:11:47.453Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.418511001Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3232026-08-31T23:11:47.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.450402335Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3242026-08-31T23:11:47.478Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.450631728Z","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"}
3252026-08-31T23:11:47.478Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.450807861Z","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"}
3262026-08-31T23:11:47.478Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.450927277Z","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 }","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3272026-08-31T23:11:47.478Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.451079705Z","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::can_migrate_from_base"}
3282026-08-31T23:11:47.478Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.451208228Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3292026-08-31T23:11:47.478Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.451381205Z","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"}
3302026-08-31T23:11:47.509Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.493664283Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3312026-08-31T23:11:47.533Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.506663375Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":55,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3322026-08-31T23:11:47.533Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.50674523Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3332026-08-31T23:11:47.533Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.506813018Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"b54842c1-aa20-48bf-a2de-7241884333b8","timeout_duration":"45s","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3342026-08-31T23:11:47.533Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.506875616Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3352026-08-31T23:11:47.533Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:47.50742231Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3362026-08-31T23:11:48.223Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:48.207996543Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: cd877725-eb67-4c50-9a9f-6cecc7244d03, name: \"phd-vm-cd877725-eb67-4c50-9a9f-6cecc7244d03\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f9d7ac0b-241e-492b-906d-cff95e9deff5, project_id: ae78e5a8-d159-46be-8e24-f7ba48421a05, sled_id: 05aa2318-36b2-4026-a35f-bb0b5da072b6, sled_serial: \"05aa2318-36b2-4026-a35f-bb0b5da072b6\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3372026-08-31T23:11:48.223Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:48.208192343Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","migration_id":"b54842c1-aa20-48bf-a2de-7241884333b8","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3382026-08-31T23:11:50.683Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:50.66891801Z","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}}"}
3392026-08-31T23:11:51.268Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.253689393Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3402026-08-31T23:11:51.268Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.253771027Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","migration_id":"b54842c1-aa20-48bf-a2de-7241884333b8","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":3044,"source":"migration_from_base","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3412026-08-31T23:11:51.292Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.256209988Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3422026-08-31T23:11:51.292Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.256468779Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3432026-08-31T23:11:51.292Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.256534763Z","target":"phd_framework::test_vm","line":920,"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":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3442026-08-31T23:11:51.292Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.257663604Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3452026-08-31T23:11:51.350Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.335866814Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":79,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3462026-08-31T23:11:51.374Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.336210784Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9599,"vm":"migration_from_base","vm_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3472026-08-31T23:11:51.374Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.336431962Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":79,"vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3482026-08-31T23:11:51.374Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.33667935Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3492026-08-31T23:11:51.374Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.336750524Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3502026-08-31T23:11:51.399Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.368009282Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3512026-08-31T23:11:51.399Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.368226242Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3522026-08-31T23:11:51.399Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.368475132Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3532026-08-31T23:11:51.399Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.368600197Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3542026-08-31T23:11:51.399Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.368642201Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8882}
3552026-08-31T23:11:51.399Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.368716507Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3562026-08-31T23:11:51.399Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.369830643Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3572026-08-31T23:11:51.869Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.854312455Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3582026-08-31T23:11:51.955Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.940697177Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3592026-08-31T23:11:51.955Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.940805953Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-bcc30f2a-8f08-4e58-b81b-6b4c707b8839\"]","verb":"destroy","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3602026-08-31T23:11:51.982Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.96798512Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3612026-08-31T23:11:52.006Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.968049642Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-83364c0b-f981-42cc-b7fe-89f574d6b48f\"]","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3622026-08-31T23:11:52.006Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.986501775Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":617,"vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3632026-08-31T23:11:52.006Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.986734104Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4478,"source":"migration_from_base","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","vm_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3642026-08-31T23:11:52.006Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.986834674Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"cd877725-eb67-4c50-9a9f-6cecc7244d03","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":4479,"source":"migration_from_base","source_id":"5ba2fabd-df78-4f91-a716-16dca677a693","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3652026-08-31T23:11:52.006Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.986805529Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":617}
3662026-08-31T23:11:52.007Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.98689568Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":10363,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3672026-08-31T23:11:52.007Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.986949241Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3682026-08-31T23:11:52.007Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.987010937Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3692026-08-31T23:11:52.007Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.98706501Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3702026-08-31T23:11:52.007Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.987248256Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3712026-08-31T23:11:52.007Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.987355118Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3722026-08-31T23:11:52.007Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.987424239Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3732026-08-31T23:11:52.007Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.987494331Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3742026-08-31T23:11:52.007Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.987573Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3752026-08-31T23:11:52.031Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.998858219Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-08-31T23:11:52.031Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:51.998970561Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-5616cece-d605-44b9-a879-5e1c5d0a9c56\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-08-31T23:11:52.031Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.016497675Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-5616cece-d605-44b9-a879-5e1c5d0a9c56\", \"phd-artifacts/phd-clone-88f75585-567b-4cc3-a84c-c24bb37ba520\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-08-31T23:11:52.055Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.034301665Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-88f75585-567b-4cc3-a84c-c24bb37ba520\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-08-31T23:11:52.079Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.045038226Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-88f75585-567b-4cc3-a84c-c24bb37ba520 0B 25.3T 1.30G /phd-artifacts/phd-clone-88f75585-567b-4cc3-a84c-c24bb37ba520\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-08-31T23:11:52.079Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.045618982Z","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"}
3812026-08-31T23:11:52.079Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.045689023Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-08-31T23:11:52.079Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.045759704Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/3c6bde1a08b3295d5b61675c8c8fffe6ff15bbfcc9c92a5e8ac0585e74d6b7c0/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-08-31T23:11:52.079Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.045830253Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/3c6bde1a08b3295d5b61675c8c8fffe6ff15bbfcc9c92a5e8ac0585e74d6b7c0/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-08-31T23:11:52.079Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.045921767Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-08-31T23:11:52.104Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 937","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.090320427Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3862026-08-31T23:11:52.128Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.10419597Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":58,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3872026-08-31T23:11:52.128Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.104306239Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3882026-08-31T23:11:52.128Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.105008025Z","target":"phd_framework::test_vm","line":455,"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":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3892026-08-31T23:11:52.807Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.792485728Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3902026-08-31T23:11:52.853Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.793733246Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: ab037ace-d584-414f-9c2f-ccc2bf9aa787, name: \"phd-vm-ab037ace-d584-414f-9c2f-ccc2bf9aa787\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: ef762a00-7b96-447d-9916-277ce1463ea7, project_id: 90a35962-2e3f-421b-9331-6f055bb15b32, sled_id: 6a2bb94e-20f6-4def-9dc4-f0149e82de19, sled_serial: \"6a2bb94e-20f6-4def-9dc4-f0149e82de19\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3912026-08-31T23:11:52.853Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.793891525Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3922026-08-31T23:11:52.853Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.793948784Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3932026-08-31T23:11:52.853Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.794838228Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":0,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3942026-08-31T23:11:52.853Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.794918564Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3952026-08-31T23:11:52.853Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.794975043Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","timeout_duration":"300s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-08-31T23:11:52.853Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.795022739Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972026-08-31T23:11:52.853Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.795073479Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3982026-08-31T23:11:52.853Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:52.795147832Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3992026-08-31T23:11:57.443Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.428963592Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":4633,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4002026-08-31T23:11:57.443Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.429061046Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012026-08-31T23:11:57.467Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.429250865Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4022026-08-31T23:11:57.467Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.429310157Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4032026-08-31T23:11:57.467Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.429354761Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4042026-08-31T23:11:57.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.44808826Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":18,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4052026-08-31T23:11:57.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.448172669Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4062026-08-31T23:11:57.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.448419546Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4072026-08-31T23:11:57.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.448479339Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4082026-08-31T23:11:57.468Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.448530826Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4092026-08-31T23:11:57.496Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.481882333Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":33,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4102026-08-31T23:11:57.496Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.482054309Z","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"}
4112026-08-31T23:11:57.520Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.482135592Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4686,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4122026-08-31T23:11:57.520Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.482379696Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4132026-08-31T23:11:57.520Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.482440777Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4142026-08-31T23:11:57.520Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.492113329Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":9,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4152026-08-31T23:11:57.520Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.492383711Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4162026-08-31T23:11:57.520Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.492490122Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4172026-08-31T23:11:57.545Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.525659184Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":33,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-08-31T23:11:57.545Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.525859653Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4192026-08-31T23:11:57.545Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.525923333Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4202026-08-31T23:11:57.570Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.536319924Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4212026-08-31T23:11:57.570Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.5364446Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4222026-08-31T23:11:57.570Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.536498622Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4232026-08-31T23:11:57.594Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.569875617Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":33,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4242026-08-31T23:11:57.594Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.570213777Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4252026-08-31T23:11:57.594Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.570343985Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4262026-08-31T23:11:57.618Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.580809382Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4272026-08-31T23:11:57.619Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.581130549Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4282026-08-31T23:11:57.619Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.581270453Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4292026-08-31T23:11:57.643Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.614067032Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4302026-08-31T23:11:57.643Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.614325801Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4312026-08-31T23:11:57.643Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.614431651Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4322026-08-31T23:11:57.643Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.625121005Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4332026-08-31T23:11:57.643Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.625367682Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4342026-08-31T23:11:57.643Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.625473512Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4352026-08-31T23:11:57.673Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.659448556Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":33,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4362026-08-31T23:11:57.697Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.659715641Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4372026-08-31T23:11:57.697Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.659823354Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4382026-08-31T23:11:57.697Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.67043962Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4392026-08-31T23:11:57.697Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.670696376Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4402026-08-31T23:11:57.697Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.670757491Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4412026-08-31T23:11:57.721Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.703721265Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4422026-08-31T23:11:57.722Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.703986737Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4432026-08-31T23:11:57.722Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.704092637Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4442026-08-31T23:11:57.746Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.714650988Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4452026-08-31T23:11:57.746Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.714885638Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4462026-08-31T23:11:57.746Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.714984975Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4472026-08-31T23:11:57.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.747326351Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4482026-08-31T23:11:57.770Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.747523324Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4492026-08-31T23:11:57.770Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.747666384Z","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"}
4502026-08-31T23:11:57.770Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.747758789Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-08-31T23:11:57.770Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.747830895Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4522026-08-31T23:11:57.770Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.747881421Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-08-31T23:11:57.770Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.747954328Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-08-31T23:11:57.802Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.788460448Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4552026-08-31T23:11:57.826Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.800246325Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":52,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4562026-08-31T23:11:57.826Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.800358718Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4572026-08-31T23:11:57.826Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.800435814Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"fd6f9c23-7b7f-4d41-831c-dbab564bfc8d","source":"migration_from_base_and_back","source_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4582026-08-31T23:11:57.826Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.800522968Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4592026-08-31T23:11:57.826Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:57.801107243Z","target":"phd_framework::test_vm","line":455,"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":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4602026-08-31T23:11:58.641Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:58.627595108Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: df70f814-1745-41b1-aacd-8993a61c5081, name: \"phd-vm-df70f814-1745-41b1-aacd-8993a61c5081\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: ef762a00-7b96-447d-9916-277ce1463ea7, project_id: 90a35962-2e3f-421b-9331-6f055bb15b32, sled_id: 7acb11b2-cb6e-4117-9640-5c6aacbcf446, sled_serial: \"7acb11b2-cb6e-4117-9640-5c6aacbcf446\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back","source_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4612026-08-31T23:11:58.642Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:11:58.62780776Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","migration_id":"fd6f9c23-7b7f-4d41-831c-dbab564bfc8d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4622026-08-31T23:12:01.081Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:01.067783623Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
4632026-08-31T23:12:01.742Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:01.728874804Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4642026-08-31T23:12:01.742Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:01.728957901Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","migration_id":"fd6f9c23-7b7f-4d41-831c-dbab564bfc8d","elapsed_milliseconds":3100,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4652026-08-31T23:12:01.767Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:01.730952401Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4662026-08-31T23:12:01.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:01.731176084Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4672026-08-31T23:12:01.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:01.731236718Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4682026-08-31T23:12:01.767Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:01.733065836Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4692026-08-31T23:12:01.827Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:01.813402508Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":82,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4702026-08-31T23:12:01.851Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:01.813608167Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","elapsed_milliseconds":9707,"vm_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4712026-08-31T23:12:03.716Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.702598412Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":1971,"vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4722026-08-31T23:12:03.741Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.702871368Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4732026-08-31T23:12:03.741Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.702931993Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4742026-08-31T23:12:03.766Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.736565132Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":33,"vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4752026-08-31T23:12:03.766Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.736734202Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__BASE_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762026-08-31T23:12:03.766Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.736877283Z","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"}
4772026-08-31T23:12:03.766Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.73693951Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_1","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-08-31T23:12:03.766Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.737010394Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/3c6bde1a08b3295d5b61675c8c8fffe6ff15bbfcc9c92a5e8ac0585e74d6b7c0/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-08-31T23:12:03.766Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.737065238Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/3c6bde1a08b3295d5b61675c8c8fffe6ff15bbfcc9c92a5e8ac0585e74d6b7c0/propolis-server\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-08-31T23:12:03.766Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.737141282Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-08-31T23:12:03.791Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 940","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.777417417Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4822026-08-31T23:12:03.816Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.789903986Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":52,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4832026-08-31T23:12:03.816Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.789983727Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"df70f814-1745-41b1-aacd-8993a61c5081","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1"}
4842026-08-31T23:12:03.816Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.790050103Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"7bf7161a-67db-49f3-815e-983d7f28fc3e","source":"migration_from_base_and_back_lifecycle_0","source_id":"df70f814-1745-41b1-aacd-8993a61c5081","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1"}
4852026-08-31T23:12:03.816Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.790110046Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"df70f814-1745-41b1-aacd-8993a61c5081","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1"}
4862026-08-31T23:12:03.816Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:03.790694992Z","target":"phd_framework::test_vm","line":455,"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":"df70f814-1745-41b1-aacd-8993a61c5081","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1"}
4872026-08-31T23:12:04.571Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:04.557566438Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c161fae5-c3df-441e-b61a-249f793ada6e, name: \"phd-vm-c161fae5-c3df-441e-b61a-249f793ada6e\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: ef762a00-7b96-447d-9916-277ce1463ea7, project_id: 90a35962-2e3f-421b-9331-6f055bb15b32, sled_id: fe222010-08c7-4384-9602-c1b032b58042, sled_serial: \"fe222010-08c7-4384-9602-c1b032b58042\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_0","source_id":"df70f814-1745-41b1-aacd-8993a61c5081","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1"}
4882026-08-31T23:12:04.596Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:04.55778948Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"df70f814-1745-41b1-aacd-8993a61c5081","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","migration_id":"7bf7161a-67db-49f3-815e-983d7f28fc3e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1"}
4892026-08-31T23:12:07.066Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.051983176Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7894}}"}
4902026-08-31T23:12:07.462Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.448807554Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"df70f814-1745-41b1-aacd-8993a61c5081","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1"}
4912026-08-31T23:12:07.462Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.448910098Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"df70f814-1745-41b1-aacd-8993a61c5081","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","migration_id":"7bf7161a-67db-49f3-815e-983d7f28fc3e","elapsed_milliseconds":2890,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1"}
4922026-08-31T23:12:07.486Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.451261853Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4932026-08-31T23:12:07.486Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.451504692Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4942026-08-31T23:12:07.486Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.451573312Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4952026-08-31T23:12:07.486Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.453017562Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4962026-08-31T23:12:07.548Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.534547123Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":83,"vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4972026-08-31T23:12:07.578Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.534760836Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","source_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":9732,"vm_id":"df70f814-1745-41b1-aacd-8993a61c5081","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4982026-08-31T23:12:07.578Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.534864814Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","source_id":"ab037ace-d584-414f-9c2f-ccc2bf9aa787","target_id":"df70f814-1745-41b1-aacd-8993a61c5081","elapsed_milliseconds":9733,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4992026-08-31T23:12:07.715Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.702224423Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":250,"vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5002026-08-31T23:12:07.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.702552152Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5012026-08-31T23:12:07.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.702663916Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5022026-08-31T23:12:07.764Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.735814619Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":33,"vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5032026-08-31T23:12:07.764Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.735977988Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5042026-08-31T23:12:07.764Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.736075833Z","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"}
5052026-08-31T23:12:07.764Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.736131408Z","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"}
5062026-08-31T23:12:07.764Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.736210788Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5072026-08-31T23:12:07.764Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.736272134Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-08-31T23:12:07.764Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.736352796Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-08-31T23:12:07.794Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 942","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.781122616Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5102026-08-31T23:12:07.818Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.79489676Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":58,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5112026-08-31T23:12:07.818Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.795002099Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"c161fae5-c3df-441e-b61a-249f793ada6e","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2"}
5122026-08-31T23:12:07.818Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.795078573Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"92305084-1f3b-4e97-9e1f-a8331c81cebd","timeout_duration":"45s","source":"migration_from_base_and_back_lifecycle_1","source_id":"c161fae5-c3df-441e-b61a-249f793ada6e","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2"}
5132026-08-31T23:12:07.818Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.795159626Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"c161fae5-c3df-441e-b61a-249f793ada6e","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2"}
5142026-08-31T23:12:07.818Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:07.795746005Z","target":"phd_framework::test_vm","line":455,"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":"c161fae5-c3df-441e-b61a-249f793ada6e","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2"}
5152026-08-31T23:12:08.529Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:08.515679354Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: abc6acba-f1d7-403c-9956-1ccd4c41e45e, name: \"phd-vm-abc6acba-f1d7-403c-9956-1ccd4c41e45e\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: ef762a00-7b96-447d-9916-277ce1463ea7, project_id: 90a35962-2e3f-421b-9331-6f055bb15b32, sled_id: ce9daf00-26e7-4137-911f-5cd34ab3b671, sled_serial: \"ce9daf00-26e7-4137-911f-5cd34ab3b671\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_1","source_id":"c161fae5-c3df-441e-b61a-249f793ada6e","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2"}
5162026-08-31T23:12:08.529Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:08.515863312Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"c161fae5-c3df-441e-b61a-249f793ada6e","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","migration_id":"92305084-1f3b-4e97-9e1f-a8331c81cebd","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2"}
5172026-08-31T23:12:11.029Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.016141105Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7941}}"}
5182026-08-31T23:12:11.604Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.590422114Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"c161fae5-c3df-441e-b61a-249f793ada6e","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2"}
5192026-08-31T23:12:11.604Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.590560916Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"c161fae5-c3df-441e-b61a-249f793ada6e","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","migration_id":"92305084-1f3b-4e97-9e1f-a8331c81cebd","elapsed_milliseconds":3074,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2"}
5202026-08-31T23:12:11.629Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.592863018Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5212026-08-31T23:12:11.629Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.593091921Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5222026-08-31T23:12:11.629Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.593156543Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5232026-08-31T23:12:11.629Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.594479281Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5242026-08-31T23:12:11.685Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.672070817Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":78,"vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5252026-08-31T23:12:11.710Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.672309177Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","source_id":"df70f814-1745-41b1-aacd-8993a61c5081","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":7881,"vm_id":"c161fae5-c3df-441e-b61a-249f793ada6e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5262026-08-31T23:12:11.710Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.67242147Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","source_id":"df70f814-1745-41b1-aacd-8993a61c5081","target_id":"c161fae5-c3df-441e-b61a-249f793ada6e","elapsed_milliseconds":7881,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1"}
5272026-08-31T23:12:11.710Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.672473478Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":79,"vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5282026-08-31T23:12:11.710Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.672780959Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5292026-08-31T23:12:11.710Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.672884976Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5302026-08-31T23:12:11.735Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.70497052Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":32,"vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5312026-08-31T23:12:11.735Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.705174495Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5322026-08-31T23:12:11.735Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.705497666Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5332026-08-31T23:12:11.735Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.705700119Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":18910}
5342026-08-31T23:12:11.735Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.705754001Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5352026-08-31T23:12:11.735Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.705885299Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5362026-08-31T23:12:11.735Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:11.707303238Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5372026-08-31T23:12:12.254Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.240345489Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5382026-08-31T23:12:12.333Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.32004686Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5392026-08-31T23:12:12.333Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.320160646Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-88f75585-567b-4cc3-a84c-c24bb37ba520\"]","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5402026-08-31T23:12:12.360Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.346716208Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5412026-08-31T23:12:12.384Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.346812771Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-5616cece-d605-44b9-a879-5e1c5d0a9c56\"]","verb":"destroy","vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5422026-08-31T23:12:12.384Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.366755413Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":661,"vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5432026-08-31T23:12:12.384Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.366929532Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","source_id":"c161fae5-c3df-441e-b61a-249f793ada6e","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":4571,"vm_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5442026-08-31T23:12:12.384Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.366999424Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","source_id":"c161fae5-c3df-441e-b61a-249f793ada6e","target_id":"abc6acba-f1d7-403c-9956-1ccd4c41e45e","elapsed_milliseconds":4571,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2"}
5452026-08-31T23:12:12.384Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.367055099Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":20377,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5462026-08-31T23:12:12.384Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.36711364Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":661}
5472026-08-31T23:12:12.384Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.367244838Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5482026-08-31T23:12:12.385Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.367299572Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5492026-08-31T23:12:12.385Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 92.19s
5502026-08-31T23:12:12.385Z
5512026-08-31T23:12:12.385Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-08-31T23:12:12.369050261Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5522026-08-31T23:12:12.514Z
5532026-08-31T23:12:12.514Zreal 1:33.344205511
5542026-08-31T23:12:12.514Zuser 49.976305193
5552026-08-31T23:12:12.514Zsys 21.766691569
5562026-08-31T23:12:12.539Ztrap 0.007185575
5572026-08-31T23:12:12.539Ztflt 0.006151309
5582026-08-31T23:12:12.539Zdflt 0.001900990
5592026-08-31T23:12:12.539Zkflt 0.000003717
5602026-08-31T23:12:12.539Zlock 3:37:22.332885196
5612026-08-31T23:12:12.539Zslp 4:19.032039960
5622026-08-31T23:12:12.539Zlat 2.114991345
5632026-08-31T23:12:12.539Zstop 49.577328522
5642026-08-31T23:12:12.539Z+ failcount=0
5652026-08-31T23:12:12.539Z+ set -e
5662026-08-31T23:12:12.539Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5672026-08-31T23:12:12.566ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5682026-08-31T23:12:12.566Za ./ 0K
5692026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::serial_history/ 0K
5702026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 158K
5712026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5722026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5732026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 165K
5742026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5752026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5762026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 158K
5772026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5782026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5792026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 164K
5802026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5812026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5822026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 158K
5832026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5842026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5852026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 269K
5862026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5872026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 269K
5882026-08-31T23:12:12.566Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5892026-08-31T23:12:12.567Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 164K
5902026-08-31T23:12:12.567Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5912026-08-31T23:12:12.567Z+ exitcode=0
5922026-08-31T23:12:12.567Z+ '[' 0 -eq 0 ']'
5932026-08-31T23:12:12.567Z+ echo
5942026-08-31T23:12:12.567Z
5952026-08-31T23:12:12.567Z+ echo 'ALL TESTS PASSED'
5962026-08-31T23:12:12.567ZALL TESTS PASSED
5972026-08-31T23:12:12.567Z+ echo
5982026-08-31T23:12:12.567Z
5992026-08-31T23:12:12.567Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6002026-08-31T23:12:12.567Z+ read
6012026-08-31T23:12:12.567Z+ exit 0
6022026-08-31T23:12:12.567Zprocess exited: duration 164587 ms, exit code 0
 
6032026-08-31T23:12:12.619Zfound 2 output files
6042026-08-31T23:12:12.620Zuploading: /tmp/phd-runner.log (184370 bytes)
6052026-08-31T23:12:13.784Zuploaded: /tmp/phd-runner.log
6062026-08-31T23:12:13.784Zuploading: /tmp/phd-tmp-files.tar.gz (133203 bytes)
6072026-08-31T23:12:14.965Zuploaded: /tmp/phd-tmp-files.tar.gz