01M1MY80WKX81JE7PMR64RPP8D: 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: 01M1MY8WX4QQXV73PBZ4MPBE13

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-09-04T01:01:07.014Zjob dependencies complete; ready to run (waiting for 11 m 32 s)
22026-09-04T01:09:22.907Zjob assigned to worker 01M1MYYQP74Q27VM7WEZM3DFZY [factory edgar, gimlet/BRM42220010/1499] (queued for 8 m 15 s)
32026-09-04T01:09:23.912Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-09-04T01:09:23.938Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-09-04T01:09:23.938Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-09-04T01:09:23.985Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-09-04T01:09:23.985Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-09-04T01:09:32.593Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-09-04T01:09:32.593Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-09-04T01:09:32.644Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-09-04T01:09:32.644Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-09-04T01:09:46.956Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-09-04T01:09:46.956Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-09-04T01:10:01.004Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-09-04T01:10:01.004Zstarting task 0: "setup"
162026-09-04T01:10:01.044Z++ uname -s
172026-09-04T01:10:01.044Z+ kern=SunOS
182026-09-04T01:10:01.044Z+ build_user=build
192026-09-04T01:10:01.044Z+ build_uid=12345
202026-09-04T01:10:01.044Z+ work_dir=/work
212026-09-04T01:10:01.044Z+ input_dir=/input
222026-09-04T01:10:01.044Z+ [[ 0 == 12345 ]]
232026-09-04T01:10:01.045Z+ case "$kern" in
242026-09-04T01:10:01.045Z+ groupadd -g 12345 build
252026-09-04T01:10:01.045Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-09-04T01:10:03.823Z+ zfs create -o mountpoint=/work rpool/work
272026-09-04T01:10:03.848Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-09-04T01:10:03.848Z+ home_fs=
292026-09-04T01:10:03.848Z+ [[ '' == autofs ]]
302026-09-04T01:10:03.848Z+ mkdir -p /home/build
312026-09-04T01:10:03.848Z+ chown build:build /home/build /work
322026-09-04T01:10:04.053Z+ chmod 0700 /home/build /work
332026-09-04T01:10:04.077Zprocess exited: duration 3126 ms, exit code 0
 
342026-09-04T01:10:04.127Zstarting task 1: "authentication"
352026-09-04T01:10:04.197Zprocess exited: duration 69 ms, exit code 0
 
362026-09-04T01:10:04.246Zstarting task 2: "build"
372026-09-04T01:10:04.274Z+ indir=/input
382026-09-04T01:10:04.274Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-09-04T01:10:04.274Z+ phddir=/work/phd-test
402026-09-04T01:10:04.274Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-09-04T01:10:04.299Z++ pilot local disk list -H -o type,disk
422026-09-04T01:10:04.299Z++ grep -v M.2
432026-09-04T01:10:04.299Z++ cut -f 2
442026-09-04T01:10:04.353Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
452026-09-04T01:10:06.924Z+ artifactdir=/phd-artifacts
462026-09-04T01:10:06.924Z+ banner Inputs
472026-09-04T01:10:06.963Z ###
482026-09-04T01:10:06.963Z # # # ##### # # ##### ####
492026-09-04T01:10:06.963Z # ## # # # # # # #
502026-09-04T01:10:06.963Z # # # # # # # # # ####
512026-09-04T01:10:06.963Z # # # # ##### # # # #
522026-09-04T01:10:06.963Z # # ## # # # # # #
532026-09-04T01:10:06.963Z ### # # # #### # ####
542026-09-04T01:10:06.963Z
552026-09-04T01:10:06.963Z+ find /input -ls
562026-09-04T01:10:06.964Z 34 1 drwxr-xr-x 3 root root 3 Sep 4 01:09 /input
572026-09-04T01:10:06.964Z 2 1 drwxr-xr-x 3 root root 3 Sep 4 01:09 /input/phd-build
582026-09-04T01:10:06.964Z 3 2 drwxr-xr-x 2 root root 8 Sep 4 01:09 /input/phd-build/out
592026-09-04T01:10:06.964Z 128 2 -rw-r--r-- 1 root root 2573 Sep 4 01:09 /input/phd-build/out/phd-run-with-args.sh
602026-09-04T01:10:06.964Z 130 187779 -rw-r--r-- 1 root root 192187458 Sep 4 01:09 /input/phd-build/out/phd-runner.tar.gz
612026-09-04T01:10:06.964Z 384 261477 -rw-r--r-- 1 root root 267704455 Sep 4 01:09 /input/phd-build/out/propolis-server-debug.tar.gz
622026-09-04T01:10:06.964Z 129 1 -rw-r--r-- 1 root root 65 Sep 4 01:09 /input/phd-build/out/phd-runner.sha256.txt
632026-09-04T01:10:06.964Z 256 1 -rw-r--r-- 1 root root 65 Sep 4 01:09 /input/phd-build/out/propolis-server-debug.sha256.txt
642026-09-04T01:10:06.964Z 257 219420 -rw-r--r-- 1 root root 224615177 Sep 4 01:10 /input/phd-build/out/propolis-tests-debug.tar.gz
652026-09-04T01:10:06.964Z+ rm -rf /work/phd-test
662026-09-04T01:10:06.964Z+ mkdir /work/phd-test
672026-09-04T01:10:06.964Z+ for p in $indir/$indir_suffix
682026-09-04T01:10:06.964Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-09-04T01:10:12.259ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-09-04T01:10:12.259Zx phd-runner, 737380920 bytes, 1440198 tape blocks
712026-09-04T01:10:12.259Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-09-04T01:10:12.293Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-09-04T01:10:17.191Z+ for f in $(tar tf "$p")
742026-09-04T01:10:17.191Z+ chmod +x /work/phd-test/phd-runner
752026-09-04T01:10:17.215Z+ for f in $(tar tf "$p")
762026-09-04T01:10:17.215Z+ chmod +x /work/phd-test/artifacts.toml
772026-09-04T01:10:17.215Z+ for p in $indir/$indir_suffix
782026-09-04T01:10:17.215Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-09-04T01:10:39.441ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-09-04T01:10:39.441Zx propolis-server, 1073533072 bytes, 2096745 tape blocks
812026-09-04T01:10:39.466Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-09-04T01:10:46.304Z+ for f in $(tar tf "$p")
832026-09-04T01:10:46.304Z+ chmod +x /work/phd-test/propolis-server
842026-09-04T01:10:46.329Z+ for p in $indir/$indir_suffix
852026-09-04T01:10:46.329Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-09-04T01:11:02.618ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-09-04T01:11:02.618Zx target/debug/deps/propolis-2a163edea74e5646, 899207800 bytes, 1756266 tape blocks
882026-09-04T01:11:02.643Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-09-04T01:11:08.238Z+ for f in $(tar tf "$p")
902026-09-04T01:11:08.238Z+ chmod +x /work/phd-test/target/debug/deps/propolis-2a163edea74e5646
912026-09-04T01:11:08.263Z+ ls /work/phd-test
922026-09-04T01:11:08.263Zartifacts.toml
932026-09-04T01:11:08.263Zphd-runner
942026-09-04T01:11:08.263Zpropolis-server
952026-09-04T01:11:08.263Ztarget
962026-09-04T01:11:08.263Z+ banner Setup
972026-09-04T01:11:08.263Z #####
982026-09-04T01:11:08.263Z# # ###### ##### # # #####
992026-09-04T01:11:08.263Z# # # # # # #
1002026-09-04T01:11:08.263Z ##### ##### # # # # #
1012026-09-04T01:11:08.263Z # # # # # #####
1022026-09-04T01:11:08.263Z# # # # # # #
1032026-09-04T01:11:08.263Z ##### ###### # #### #
1042026-09-04T01:11:08.263Z
1052026-09-04T01:11:08.264Z+ tmpdir=/tmp/propolis-phd
1062026-09-04T01:11:08.264Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-09-04T01:11:08.264Z+ mkdir /tmp/propolis-phd
1082026-09-04T01:11:08.264Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-09-04T01:11:08.722Z+ banner Tests
1102026-09-04T01:11:08.747Z#######
1112026-09-04T01:11:08.747Z # ###### #### ##### ####
1122026-09-04T01:11:08.747Z # # # # #
1132026-09-04T01:11:08.747Z # ##### #### # ####
1142026-09-04T01:11:08.747Z # # # # #
1152026-09-04T01:11:08.747Z # # # # # # #
1162026-09-04T01:11:08.748Z # ###### #### # ####
1172026-09-04T01:11:08.748Z
1182026-09-04T01:11:08.748Z+ runner=/work/phd-test/phd-runner
1192026-09-04T01:11:08.748Z+ artifacts=/work/phd-test/artifacts.toml
1202026-09-04T01:11:08.748Z+ propolis=/work/phd-test/propolis-server
1212026-09-04T01:11:08.748Z+ ls /work/phd-test/phd-runner
1222026-09-04T01:11:08.748Z/work/phd-test/phd-runner
1232026-09-04T01:11:08.748Z+ ls /work/phd-test/artifacts.toml
1242026-09-04T01:11:08.748Z/work/phd-test/artifacts.toml
1252026-09-04T01:11:08.748Z+ ls /work/phd-test/propolis-server
1262026-09-04T01:11:08.748Z/work/phd-test/propolis-server
1272026-09-04T01:11:08.748Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-09-04T01:11:08.748Z+ set +e
1292026-09-04T01:11:08.748Z+ RUST_BACKTRACE=1
1302026-09-04T01:11:08.748Z+ RUST_LOG=info,phd=debug
1312026-09-04T01:11:08.748Z+ 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-09-04T01:11:08.748Z+ tee /tmp/phd-runner.log
1332026-09-04T01:11:08.937Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:08.912737477Z","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-09-04T01:11:08.962Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:08.937067797Z","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: 252, tv_nsec: 170350428 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-09-04T01:11:08.962Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:08.937663661Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-09-04T01:11:08.962Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:08.939461854Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"ad8a31742adc45e925e63443a5b43c8e30604022"}
1372026-09-04T01:11:08.987Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:08.944603265Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/ad8a31742adc45e925e63443a5b43c8e30604022/crucible-nightly.sha256.txt"}
1382026-09-04T01:11:09.228Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:09.210278767Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-09-04T01:11:13.156Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.137621132Z","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/3a19c4ae56827d6cb2369df72724c4edfebf42de/propolis-server.sha256.txt","timeout":"600s"}
1402026-09-04T01:11:13.357Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.339234271Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-09-04T01:11:13.383Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.339317699Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-09-04T01:11:13.383Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.343211816Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-09-04T01:11:13.383Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.344036262Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-09-04T01:11:13.383Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.344073111Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-09-04T01:11:13.383Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.344105302Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-09-04T01:11:13.383Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.345496627Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
1472026-09-04T01:11:13.383Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.347593776Z","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-09-04T01:11:13.383Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.349667358Z","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-09-04T01:11:13.856Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.836582022Z","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-09-04T01:11:13.880Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:13.849613693Z","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-09-04T01:11:20.507Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.48720424Z","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-09-04T01:11:20.531Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.487993288Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::serial_history"}
1532026-09-04T01:11:20.531Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.50309209Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 5.07M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
1542026-09-04T01:11:20.531Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.505420574Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-a95f1154-661e-4abf-9655-26744b9f1976\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::serial_history"}
1552026-09-04T01:11:20.556Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.529874017Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-a95f1154-661e-4abf-9655-26744b9f1976\", \"phd-artifacts/phd-clone-e6e2dd7e-9952-4916-b8c4-7ce299bb3075\"]","path":"phd_tests::migrate::from_base::serial_history"}
1562026-09-04T01:11:20.580Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.550735873Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-e6e2dd7e-9952-4916-b8c4-7ce299bb3075\"]","verb":"list","path":"phd_tests::migrate::from_base::serial_history"}
1572026-09-04T01:11:20.605Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.562243437Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-e6e2dd7e-9952-4916-b8c4-7ce299bb3075 0B 25.3T 49.0M /phd-artifacts/phd-clone-e6e2dd7e-9952-4916-b8c4-7ce299bb3075\n","path":"phd_tests::migrate::from_base::serial_history"}
1582026-09-04T01:11:20.605Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.566575722Z","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-09-04T01:11:20.605Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.566708813Z","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_serial_history_base","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
1602026-09-04T01:11:20.605Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.566789625Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/573bf3f8ac65fa564fd8820473cb7e95089af7426236b1501d8ef3c45c2e1337/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1612026-09-04T01:11:20.605Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:20.566863424Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/3a19c4ae56827d6cb2369df72724c4edfebf42de/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1622026-09-04T01:11:40.777Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:40.755942466Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","untar_path":"propolis-server","extracted_path":"/phd-artifacts/573bf3f8ac65fa564fd8820473cb7e95089af7426236b1501d8ef3c45c2e1337/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
1632026-09-04T01:11:40.777Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:11:40.756026565Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::serial_history"}
1642026-09-04T01:12:05.383Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:05.362041057Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/573bf3f8ac65fa564fd8820473cb7e95089af7426236b1501d8ef3c45c2e1337/propolis-server\"","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::serial_history"}
1652026-09-04T01:12:05.407Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:05.362560687Z","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-09-04T01:12:05.515Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 917","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:05.4939656Z","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-09-04T01:12:05.539Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:05.509736364Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1682026-09-04T01:12:05.563Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:05.522305149Z","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)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1692026-09-04T01:12:05.563Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:05.5253797Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":44958,"path":"phd_tests::migrate::from_base::serial_history"}
1702026-09-04T01:12:06.050Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.029214764Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-09-04T01:12:06.096Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.033077372Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 0ce84cff-e40b-44ab-8635-5f78ebf26179, name: \"phd-vm-0ce84cff-e40b-44ab-8635-5f78ebf26179\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 81b37bfb-35ba-46d0-bd9a-e6c8350f4cb3, project_id: 8caca520-f78a-4bfa-84fc-61f69f13d0e7, sled_id: d4eae58e-f2a2-4aa0-bf65-02e6c7651645, sled_serial: \"d4eae58e-f2a2-4aa0-bf65-02e6c7651645\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1722026-09-04T01:12:06.096Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.033270827Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1732026-09-04T01:12:06.096Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.033338384Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1742026-09-04T01:12:06.097Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.03495274Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":1,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1752026-09-04T01:12:06.097Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.035128261Z","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-09-04T01:12:06.097Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.035232749Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","timeout_duration":"300s","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","path":"phd_tests::migrate::from_base::serial_history"}
1772026-09-04T01:12:06.097Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.035308361Z","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-09-04T01:12:06.097Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.03537112Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1792026-09-04T01:12:06.097Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:06.035457503Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1802026-09-04T01:12:10.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.633257993Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":4597,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1812026-09-04T01:12:10.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.633353714Z","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-09-04T01:12:10.679Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.637084623Z","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-09-04T01:12:10.679Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.637142322Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1842026-09-04T01:12:10.679Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.637184812Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1852026-09-04T01:12:10.703Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.662663764Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":25,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1862026-09-04T01:12:10.703Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.662827319Z","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-09-04T01:12:10.703Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.663287328Z","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-09-04T01:12:10.703Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.663386486Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1892026-09-04T01:12:10.703Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.6634681Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1902026-09-04T01:12:10.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.695753999Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1912026-09-04T01:12:10.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.695878655Z","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-09-04T01:12:10.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.695954798Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4660,"path":"phd_tests::migrate::from_base::serial_history"}
1932026-09-04T01:12:10.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.697018776Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1942026-09-04T01:12:10.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.697085802Z","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!","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1952026-09-04T01:12:10.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.70654511Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":9,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1962026-09-04T01:12:10.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.706759394Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1972026-09-04T01:12:10.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.706820009Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
1982026-09-04T01:12:10.775Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.738902601Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1992026-09-04T01:12:10.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.739150388Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
2002026-09-04T01:12:10.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.739253473Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
2012026-09-04T01:12:10.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.750142238Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2022026-09-04T01:12:10.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.75037645Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
2032026-09-04T01:12:10.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.750480766Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
2042026-09-04T01:12:10.805Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.78357101Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2052026-09-04T01:12:10.829Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.79382677Z","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-09-04T01:12:10.829Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.793909837Z","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-09-04T01:12:10.829Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.793955994Z","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_serial_history_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
2082026-09-04T01:12:10.829Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.794048188Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","sha256":"None","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2092026-09-04T01:12:10.829Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.794108291Z","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-09-04T01:12:10.829Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.794162333Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::serial_history"}
2112026-09-04T01:12:10.829Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.79422959Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2122026-09-04T01:12:10.859Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 918","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.837669471Z","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-09-04T01:12:10.884Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.851417691Z","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-09-04T01:12:10.884Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.851501489Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2152026-09-04T01:12:10.884Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.852034064Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"047da835-13b6-4903-ab47-ace594ecebc4","source_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2162026-09-04T01:12:10.884Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.852114195Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","vm":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2172026-09-04T01:12:10.884Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:10.853111667Z","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_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","vm":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2182026-09-04T01:12:11.516Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:11.494775703Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 3b344fe5-68c7-4f7f-a9f9-9065ae21a769, name: \"phd-vm-3b344fe5-68c7-4f7f-a9f9-9065ae21a769\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 81b37bfb-35ba-46d0-bd9a-e6c8350f4cb3, project_id: 8caca520-f78a-4bfa-84fc-61f69f13d0e7, sled_id: 5af0e59b-9028-41b0-aae4-07c5c18ab047, sled_serial: \"5af0e59b-9028-41b0-aae4-07c5c18ab047\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","vm":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2192026-09-04T01:12:11.541Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:11.495485622Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","migration_id":"047da835-13b6-4903-ab47-ace594ecebc4","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2202026-09-04T01:12:14.063Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.041804291Z","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-09-04T01:12:14.370Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.348786448Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2222026-09-04T01:12:14.370Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.348864175Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","migration_id":"047da835-13b6-4903-ab47-ace594ecebc4","source":"migration_serial_history_base","elapsed_milliseconds":2853,"path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2232026-09-04T01:12:14.395Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.35221624Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
2242026-09-04T01:12:14.395Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.355784202Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179"}
2252026-09-04T01:12:14.453Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.431328315Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":77,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2262026-09-04T01:12:14.477Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.431545165Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","elapsed_milliseconds":8921,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2272026-09-04T01:12:14.477Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.435829819Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2282026-09-04T01:12:14.477Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.436080111Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2292026-09-04T01:12:14.477Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.436745487Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8407}
2302026-09-04T01:12:14.477Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.437645174Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2312026-09-04T01:12:14.477Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.438120802Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2322026-09-04T01:12:14.477Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.438224487Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2332026-09-04T01:12:14.824Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.792499623Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2342026-09-04T01:12:14.904Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.88195686Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2352026-09-04T01:12:14.904Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.882063811Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-e6e2dd7e-9952-4916-b8c4-7ce299bb3075\"]","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2362026-09-04T01:12:14.930Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.908349185Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2372026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.908445336Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-a95f1154-661e-4abf-9655-26744b9f1976\"]","verb":"destroy","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2382026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.927176188Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769","elapsed_milliseconds":491,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2392026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.927392516Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","path":"phd_tests::migrate::from_base::serial_history","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769","source":"migration_serial_history_base","vm_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769","elapsed_milliseconds":4075,"vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0"}
2402026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.927475122Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0ce84cff-e40b-44ab-8635-5f78ebf26179","source":"migration_serial_history_base","elapsed_milliseconds":4075,"path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","target_id":"3b344fe5-68c7-4f7f-a9f9-9065ae21a769"}
2412026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.92753248Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":61582,"path":"phd_tests::migrate::from_base::serial_history"}
2422026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.928458317Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":490}
2432026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.928564888Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2442026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.928612718Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2452026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.92865611Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2462026-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.92883065Z","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-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.928932802Z","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-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.929001923Z","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-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.929074119Z","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-09-04T01:12:14.955Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.9291491Z","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-09-04T01:12:14.981Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.941212953Z","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-09-04T01:12:14.981Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.941354169Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-8ea76e35-a2b9-42ca-bb44-6c16074dfaa6\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-09-04T01:12:15.005Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.961498706Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-8ea76e35-a2b9-42ca-bb44-6c16074dfaa6\", \"phd-artifacts/phd-clone-2948aaee-7ba0-4b76-9bd0-7d427b2cc48f\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-09-04T01:12:15.005Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.983284402Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-2948aaee-7ba0-4b76-9bd0-7d427b2cc48f\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-09-04T01:12:15.030Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.99460955Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-2948aaee-7ba0-4b76-9bd0-7d427b2cc48f 0B 25.3T 1.30G /phd-artifacts/phd-clone-2948aaee-7ba0-4b76-9bd0-7d427b2cc48f\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-09-04T01:12:15.030Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.995175287Z","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-09-04T01:12:15.030Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.995244759Z","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 }","guest_os_kind":"Alpine","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2582026-09-04T01:12:15.030Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.995328777Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/573bf3f8ac65fa564fd8820473cb7e95089af7426236b1501d8ef3c45c2e1337/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2592026-09-04T01:12:15.030Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.995395072Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/573bf3f8ac65fa564fd8820473cb7e95089af7426236b1501d8ef3c45c2e1337/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2602026-09-04T01:12:15.030Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:14.995480523Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2612026-09-04T01:12:15.058Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 927","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.037011963Z","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-09-04T01:12:15.082Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.051170588Z","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","elapsed_milliseconds":55}
2632026-09-04T01:12:15.082Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.051328516Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2642026-09-04T01:12:15.082Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.052200832Z","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)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2652026-09-04T01:12:15.721Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.699196958Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2662026-09-04T01:12:15.767Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.700187627Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 32b68cf7-c811-4648-a62c-47d4079b2fa6, name: \"phd-vm-32b68cf7-c811-4648-a62c-47d4079b2fa6\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 4f0839a0-6602-4d48-889e-195531991ced, project_id: 7bfb620c-b8db-46ab-9ef3-c00b1448f48a, sled_id: 74f694bb-c706-40cb-b217-1041d7919028, sled_serial: \"74f694bb-c706-40cb-b217-1041d7919028\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2672026-09-04T01:12:15.767Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.700365002Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2682026-09-04T01:12:15.767Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.700433461Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2692026-09-04T01:12:15.767Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.701278195Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":0}
2702026-09-04T01:12:15.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.701369156Z","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-09-04T01:12:15.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.7014399Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","vm":"migration_from_base","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-09-04T01:12:15.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.701504211Z","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-09-04T01:12:15.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.701552723Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2742026-09-04T01:12:15.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:15.701603669Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2752026-09-04T01:12:20.316Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.293307786Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":4591}
2762026-09-04T01:12:20.316Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.29342114Z","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-09-04T01:12:20.316Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.293676562Z","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-09-04T01:12:20.316Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.293753968Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2792026-09-04T01:12:20.316Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.293812789Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2802026-09-04T01:12:20.344Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.322239916Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":28}
2812026-09-04T01:12:20.345Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.322398465Z","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-09-04T01:12:20.345Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.322786397Z","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-09-04T01:12:20.345Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.322891786Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2842026-09-04T01:12:20.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.322978449Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2852026-09-04T01:12:20.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.35459917Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":31}
2862026-09-04T01:12:20.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.354730698Z","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-09-04T01:12:20.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.354809216Z","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","elapsed_milliseconds":4653}
2882026-09-04T01:12:20.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.355042987Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2892026-09-04T01:12:20.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.355148687Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2902026-09-04T01:12:20.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.36572907Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":10}
2912026-09-04T01:12:20.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.365970315Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2922026-09-04T01:12:20.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.366088107Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2932026-09-04T01:12:20.421Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.398676934Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":32}
2942026-09-04T01:12:20.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.399661452Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2952026-09-04T01:12:20.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.399732205Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2962026-09-04T01:12:20.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.410219663Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":10}
2972026-09-04T01:12:20.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.410466369Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2982026-09-04T01:12:20.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.410568882Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
2992026-09-04T01:12:20.469Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.443292183Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":32}
3002026-09-04T01:12:20.469Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.44353983Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3012026-09-04T01:12:20.469Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.443653585Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3022026-09-04T01:12:20.493Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.454269314Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":10}
3032026-09-04T01:12:20.493Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.454512794Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3042026-09-04T01:12:20.493Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.454643991Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3052026-09-04T01:12:20.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.487610242Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":32}
3062026-09-04T01:12:20.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.487851217Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3072026-09-04T01:12:20.518Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.487954823Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3082026-09-04T01:12:20.542Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.499504142Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":11}
3092026-09-04T01:12:20.542Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.499809418Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3102026-09-04T01:12:20.542Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.499939734Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3112026-09-04T01:12:20.566Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.522504419Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":22}
3122026-09-04T01:12:20.566Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.522766013Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3132026-09-04T01:12:20.566Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.52288642Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3142026-09-04T01:12:20.566Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.53423377Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":11}
3152026-09-04T01:12:20.566Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.534473793Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3162026-09-04T01:12:20.566Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.534579012Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3172026-09-04T01:12:20.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.56722707Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":32}
3182026-09-04T01:12:20.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.568396677Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3192026-09-04T01:12:20.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.568452583Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3202026-09-04T01:12:20.615Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.578112189Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":9}
3212026-09-04T01:12:20.615Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.57836212Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3222026-09-04T01:12:20.615Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.578469753Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3232026-09-04T01:12:20.639Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.611308782Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":32}
3242026-09-04T01:12:20.639Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.611525481Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3252026-09-04T01:12:20.639Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.611665315Z","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-09-04T01:12:20.639Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.611760935Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3272026-09-04T01:12:20.639Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.611824806Z","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-09-04T01:12:20.639Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.611878948Z","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::can_migrate_from_base"}
3292026-09-04T01:12:20.639Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.611951846Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3302026-09-04T01:12:20.675Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.652712293Z","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-09-04T01:12:20.699Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.665811046Z","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","elapsed_milliseconds":54}
3322026-09-04T01:12:20.699Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.665910824Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
3332026-09-04T01:12:20.699Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.665990835Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"a910a128-4186-4f55-bdd0-e84f43e08cc9","timeout_duration":"45s","source":"migration_from_base","target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
3342026-09-04T01:12:20.699Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.666054415Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","vm":"migration_from_base_lifecycle_0","source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3352026-09-04T01:12:20.699Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:20.666632035Z","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","target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","vm":"migration_from_base_lifecycle_0","source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3362026-09-04T01:12:21.346Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:21.323870174Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 970e190e-9212-46f5-9cf1-435a3de5a0e1, name: \"phd-vm-970e190e-9212-46f5-9cf1-435a3de5a0e1\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 4f0839a0-6602-4d48-889e-195531991ced, project_id: 7bfb620c-b8db-46ab-9ef3-c00b1448f48a, sled_id: 28769875-386f-411d-abca-c6ffd0d6b4b5, sled_serial: \"28769875-386f-411d-abca-c6ffd0d6b4b5\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base","target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","vm":"migration_from_base_lifecycle_0","source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3372026-09-04T01:12:21.370Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:21.32409057Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","migration_id":"a910a128-4186-4f55-bdd0-e84f43e08cc9"}
3382026-09-04T01:12:23.897Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:23.853049194Z","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-09-04T01:12:24.314Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.289914781Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
3402026-09-04T01:12:24.314Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.289994071Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","elapsed_milliseconds":2965,"target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","migration_id":"a910a128-4186-4f55-bdd0-e84f43e08cc9"}
3412026-09-04T01:12:24.338Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.292480181Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3422026-09-04T01:12:24.338Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.292699766Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3432026-09-04T01:12:24.338Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.292763736Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3442026-09-04T01:12:24.339Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.294406927Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6"}
3452026-09-04T01:12:24.392Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.369864858Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":77}
3462026-09-04T01:12:24.416Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.370160365Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","elapsed_milliseconds":9318}
3472026-09-04T01:12:24.416Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.370398505Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","elapsed_milliseconds":77}
3482026-09-04T01:12:24.416Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.370714591Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3492026-09-04T01:12:24.417Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.370820922Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3502026-09-04T01:12:24.441Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.402758041Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","elapsed_milliseconds":31}
3512026-09-04T01:12:24.441Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.402938281Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3522026-09-04T01:12:24.441Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.403243888Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3532026-09-04T01:12:24.441Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.403424939Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8703}
3542026-09-04T01:12:24.441Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.403641638Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3552026-09-04T01:12:24.441Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.40379132Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3562026-09-04T01:12:24.441Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:24.404888731Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3572026-09-04T01:12:25.149Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.126370493Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3582026-09-04T01:12:25.240Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.218084518Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3592026-09-04T01:12:25.240Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.218190698Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-2948aaee-7ba0-4b76-9bd0-7d427b2cc48f\"]","verb":"destroy","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3602026-09-04T01:12:25.267Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.245107914Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3612026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.245206971Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-8ea76e35-a2b9-42ca-bb44-6c16074dfaa6\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3622026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.263843685Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","elapsed_milliseconds":860}
3632026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.264018474Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4597,"source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","source":"migration_from_base","target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","vm_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1"}
3642026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.264093346Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","target_id":"970e190e-9212-46f5-9cf1-435a3de5a0e1","source_id":"32b68cf7-c811-4648-a62c-47d4079b2fa6","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":4598}
3652026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.264153339Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10335}
3662026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.264134584Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":860}
3672026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.264258718Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3682026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.26430778Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3692026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.264350852Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3702026-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.264528166Z","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-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.264632303Z","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-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.26469976Z","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-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.264766366Z","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-09-04T01:12:25.292Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.26484305Z","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-09-04T01:12:25.321Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.276408911Z","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-09-04T01:12:25.321Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.276528386Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-19b1116f-dd82-4d4e-95b9-6e2863089f93\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-09-04T01:12:25.321Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.29329407Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-19b1116f-dd82-4d4e-95b9-6e2863089f93\", \"phd-artifacts/phd-clone-ceda6118-c467-4466-a0eb-b1351e522518\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-09-04T01:12:25.346Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.31323234Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-ceda6118-c467-4466-a0eb-b1351e522518\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-09-04T01:12:25.346Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.3235725Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-ceda6118-c467-4466-a0eb-b1351e522518 0B 25.3T 1.30G /phd-artifacts/phd-clone-ceda6118-c467-4466-a0eb-b1351e522518\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-09-04T01:12:25.370Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.32411305Z","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-09-04T01:12:25.370Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.324183372Z","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_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-09-04T01:12:25.370Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.324254907Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/573bf3f8ac65fa564fd8820473cb7e95089af7426236b1501d8ef3c45c2e1337/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-09-04T01:12:25.370Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.324329378Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/573bf3f8ac65fa564fd8820473cb7e95089af7426236b1501d8ef3c45c2e1337/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-09-04T01:12:25.370Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.324409329Z","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-09-04T01:12:25.396Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 937","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.365360273Z","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-09-04T01:12:25.420Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.379463343Z","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::migration_from_base_and_back"}
3872026-09-04T01:12:25.420Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.379593789Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3882026-09-04T01:12:25.420Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:25.380333986Z","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":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3892026-09-04T01:12:26.153Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.131213208Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3902026-09-04T01:12:26.200Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.132791907Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 5c4824e2-21eb-4cf2-8d6b-2217bbae2019, name: \"phd-vm-5c4824e2-21eb-4cf2-8d6b-2217bbae2019\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 00cabd5b-c917-4e57-97ba-ff7b1b97786a, project_id: dd97f43f-fed1-4ebb-92c1-cf4b328bc8d8, sled_id: 0f7ba73b-a2bf-4416-9e01-99264c596490, sled_serial: \"0f7ba73b-a2bf-4416-9e01-99264c596490\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3912026-09-04T01:12:26.200Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.13302673Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3922026-09-04T01:12:26.200Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.133109335Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3932026-09-04T01:12:26.200Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.134025364Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3942026-09-04T01:12:26.200Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.134111747Z","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-09-04T01:12:26.200Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.134173523Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","timeout_duration":"300s","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-09-04T01:12:26.200Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.134241301Z","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-09-04T01:12:26.200Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.134290113Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3982026-09-04T01:12:26.200Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:26.134342142Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3992026-09-04T01:12:30.745Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.722499521Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4588,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4002026-09-04T01:12:30.745Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.722596063Z","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-09-04T01:12:30.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.722797613Z","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-09-04T01:12:30.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.72285424Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4032026-09-04T01:12:30.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.722899225Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4042026-09-04T01:12:30.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.741041122Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4052026-09-04T01:12:30.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.741159806Z","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-09-04T01:12:30.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.741585329Z","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-09-04T01:12:30.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.741696428Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4082026-09-04T01:12:30.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.741783753Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4092026-09-04T01:12:30.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.77374903Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4102026-09-04T01:12:30.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.773909683Z","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-09-04T01:12:30.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.773988982Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4640,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4122026-09-04T01:12:30.821Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.774294769Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4132026-09-04T01:12:30.821Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.774403484Z","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":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4142026-09-04T01:12:30.821Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.78491168Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4152026-09-04T01:12:30.821Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.785183382Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4162026-09-04T01:12:30.821Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.785304411Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4172026-09-04T01:12:30.846Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.818507971Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-09-04T01:12:30.846Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.81877724Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4192026-09-04T01:12:30.846Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.818882819Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4202026-09-04T01:12:30.869Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.829649532Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4212026-09-04T01:12:30.869Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.829958795Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4222026-09-04T01:12:30.869Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.830020802Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4232026-09-04T01:12:30.894Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.862576982Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4242026-09-04T01:12:30.894Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.86290458Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4252026-09-04T01:12:30.894Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.863018194Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4262026-09-04T01:12:30.918Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.873554472Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4272026-09-04T01:12:30.918Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.873804795Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4282026-09-04T01:12:30.918Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.873908881Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4292026-09-04T01:12:30.942Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.907319904Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4302026-09-04T01:12:30.943Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.907621323Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4312026-09-04T01:12:30.943Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.907762028Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4322026-09-04T01:12:30.943Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.919274278Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4332026-09-04T01:12:30.943Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.919516154Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4342026-09-04T01:12:30.943Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.91962006Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4352026-09-04T01:12:30.967Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.942961687Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":23,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4362026-09-04T01:12:30.967Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.943202953Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4372026-09-04T01:12:30.967Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.943264779Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4382026-09-04T01:12:30.991Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.954030813Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4392026-09-04T01:12:30.991Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.954265752Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4402026-09-04T01:12:30.991Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.954322795Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4412026-09-04T01:12:31.016Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.986705134Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4422026-09-04T01:12:31.017Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.987050996Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4432026-09-04T01:12:31.017Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.98716968Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4442026-09-04T01:12:31.041Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.997874596Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4452026-09-04T01:12:31.041Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.998121823Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4462026-09-04T01:12:31.041Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:30.998227522Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4472026-09-04T01:12:31.065Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.031956565Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4482026-09-04T01:12:31.066Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.032192149Z","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-09-04T01:12:31.066Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.032338516Z","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-09-04T01:12:31.066Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.032400212Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-09-04T01:12:31.066Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.032465926Z","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-09-04T01:12:31.066Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.032522042Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-09-04T01:12:31.066Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.032596312Z","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-09-04T01:12:31.097Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.074136503Z","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-09-04T01:12:31.122Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.088024734Z","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::migration_from_base_and_back"}
4562026-09-04T01:12:31.122Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.088143037Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4572026-09-04T01:12:31.122Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.088231794Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"32353415-1157-4a35-a3a9-62f75ac5ea99","timeout_duration":"45s","source":"migration_from_base_and_back","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4582026-09-04T01:12:31.122Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.088310042Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4592026-09-04T01:12:31.122Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.088932416Z","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","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4602026-09-04T01:12:31.758Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.73581888Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 194a419f-9d00-476d-ae65-3bd7c9fbf126, name: \"phd-vm-194a419f-9d00-476d-ae65-3bd7c9fbf126\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 00cabd5b-c917-4e57-97ba-ff7b1b97786a, project_id: dd97f43f-fed1-4ebb-92c1-cf4b328bc8d8, sled_id: 53efd678-8829-4a20-80ec-b827a22a8f39, sled_serial: \"53efd678-8829-4a20-80ec-b827a22a8f39\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4612026-09-04T01:12:31.758Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:31.735974358Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","target":"migration_from_base_and_back_lifecycle_0","migration_id":"32353415-1157-4a35-a3a9-62f75ac5ea99","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4622026-09-04T01:12:34.250Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.227875366Z","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-09-04T01:12:34.566Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.54356574Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4642026-09-04T01:12:34.566Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.543670227Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","target":"migration_from_base_and_back_lifecycle_0","migration_id":"32353415-1157-4a35-a3a9-62f75ac5ea99","elapsed_milliseconds":2807,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4652026-09-04T01:12:34.591Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.546148964Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4662026-09-04T01:12:34.591Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.54642235Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4672026-09-04T01:12:34.591Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.546495578Z","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":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4682026-09-04T01:12:34.591Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.547881914Z","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":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4692026-09-04T01:12:34.648Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.625686214Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":79,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4702026-09-04T01:12:34.673Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.625876342Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":79,"vm":"migration_from_base_and_back_lifecycle_0","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4712026-09-04T01:12:34.674Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.626096443Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4722026-09-04T01:12:34.674Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.626066757Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9246,"vm":"migration_from_base_and_back","vm_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4732026-09-04T01:12:34.674Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.626160383Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4742026-09-04T01:12:34.698Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.65842246Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back_lifecycle_0","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4752026-09-04T01:12:34.698Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.658539771Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__BASE_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762026-09-04T01:12:34.698Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.658646082Z","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-09-04T01:12:34.698Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.658707638Z","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_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-09-04T01:12:34.699Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.658794943Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/573bf3f8ac65fa564fd8820473cb7e95089af7426236b1501d8ef3c45c2e1337/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-09-04T01:12:34.699Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.658861759Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9004","server_path":"\"/phd-artifacts/573bf3f8ac65fa564fd8820473cb7e95089af7426236b1501d8ef3c45c2e1337/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-09-04T01:12:34.699Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.658944224Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-09-04T01:12:34.728Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 940","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.70479682Z","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-09-04T01:12:34.753Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.71851794Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":59,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4832026-09-04T01:12:34.753Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.718611144Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","target_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
4842026-09-04T01:12:34.753Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.718685252Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"7733250f-ec40-4a83-915a-3a3e611ac5a4","timeout_duration":"45s","source":"migration_from_base_and_back_lifecycle_0","target_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
4852026-09-04T01:12:34.753Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.718769279Z","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":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
4862026-09-04T01:12:34.753Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:34.719455915Z","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","target_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
4872026-09-04T01:12:35.320Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:35.297281395Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 2aac2086-b6bc-4efa-bab7-25c130ebdb3a, name: \"phd-vm-2aac2086-b6bc-4efa-bab7-25c130ebdb3a\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 00cabd5b-c917-4e57-97ba-ff7b1b97786a, project_id: dd97f43f-fed1-4ebb-92c1-cf4b328bc8d8, sled_id: 58b0700d-6762-4282-8bae-2f95fc407745, sled_serial: \"58b0700d-6762-4282-8bae-2f95fc407745\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_0","target_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
4882026-09-04T01:12:35.320Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:35.297497232Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","target_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","target":"migration_from_base_and_back_lifecycle_1","migration_id":"7733250f-ec40-4a83-915a-3a3e611ac5a4","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
4892026-09-04T01:12:37.794Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:37.771942608Z","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-09-04T01:12:38.841Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:38.818497995Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","target_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
4912026-09-04T01:12:38.841Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:38.818560352Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","target_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","target":"migration_from_base_and_back_lifecycle_1","migration_id":"7733250f-ec40-4a83-915a-3a3e611ac5a4","elapsed_milliseconds":3520,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
4922026-09-04T01:12:38.865Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:38.820999114Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4932026-09-04T01:12:38.865Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:38.82125165Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4942026-09-04T01:12:38.865Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:38.821317845Z","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":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4952026-09-04T01:12:38.865Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:38.822642855Z","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":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4962026-09-04T01:12:38.932Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:38.910392365Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":89,"vm":"migration_from_base_and_back_lifecycle_0","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4972026-09-04T01:12:38.957Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:38.910751312Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","vm_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","elapsed_milliseconds":7821,"vm":"migration_from_base_and_back_lifecycle_0","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4982026-09-04T01:12:38.957Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:38.910887529Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","target_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":7821,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5c4824e2-21eb-4cf2-8d6b-2217bbae2019"}
4992026-09-04T01:12:41.062Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.040180968Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":2218,"vm":"migration_from_base_and_back_lifecycle_1","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5002026-09-04T01:12:41.087Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.040478048Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5012026-09-04T01:12:41.087Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.040540807Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5022026-09-04T01:12:41.111Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.072503218Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm":"migration_from_base_and_back_lifecycle_1","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5032026-09-04T01:12:41.112Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.072675786Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5042026-09-04T01:12:41.112Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.072814591Z","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-09-04T01:12:41.112Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.072901663Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-09-04T01:12:41.112Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.073016414Z","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-09-04T01:12:41.112Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.073107231Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9006","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-09-04T01:12:41.112Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.073252997Z","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-09-04T01:12:41.138Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 942","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.116462672Z","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-09-04T01:12:41.163Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.129173229Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":56,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5112026-09-04T01:12:41.163Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.129253593Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","target_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5122026-09-04T01:12:41.163Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.129314937Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"f868ec43-aa3b-4e54-83d6-7d96a69e31dc","source":"migration_from_base_and_back_lifecycle_1","target_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5132026-09-04T01:12:41.163Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.129385496Z","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":"e0407416-9b32-470c-b5a5-2879b1befd4d","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5142026-09-04T01:12:41.163Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.1299838Z","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","target_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5152026-09-04T01:12:41.975Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.951473999Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: e0407416-9b32-470c-b5a5-2879b1befd4d, name: \"phd-vm-e0407416-9b32-470c-b5a5-2879b1befd4d\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 00cabd5b-c917-4e57-97ba-ff7b1b97786a, project_id: dd97f43f-fed1-4ebb-92c1-cf4b328bc8d8, sled_id: f3856ca8-a4a8-40e3-ba90-45221f589dc0, sled_serial: \"f3856ca8-a4a8-40e3-ba90-45221f589dc0\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_1","target_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5162026-09-04T01:12:41.975Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:41.95168104Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","target_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","target":"migration_from_base_and_back_lifecycle_2","migration_id":"f868ec43-aa3b-4e54-83d6-7d96a69e31dc","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5172026-09-04T01:12:44.496Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:44.471763214Z","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-09-04T01:12:45.273Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.251029552Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","target_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5192026-09-04T01:12:45.273Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.251120343Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","target_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","target":"migration_from_base_and_back_lifecycle_2","migration_id":"f868ec43-aa3b-4e54-83d6-7d96a69e31dc","elapsed_milliseconds":3299,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5202026-09-04T01:12:45.297Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.253221778Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5212026-09-04T01:12:45.298Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.253476779Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5222026-09-04T01:12:45.298Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.253543565Z","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":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5232026-09-04T01:12:45.298Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.255460081Z","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":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5242026-09-04T01:12:45.356Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.333634234Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":80,"vm":"migration_from_base_and_back_lifecycle_1","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5252026-09-04T01:12:45.356Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.333782253Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","vm_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":10613,"vm":"migration_from_base_and_back_lifecycle_1","target_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
5262026-09-04T01:12:45.380Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.333844621Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","target_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":10613,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"194a419f-9d00-476d-ae65-3bd7c9fbf126"}
5272026-09-04T01:12:45.380Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.334123036Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":80,"vm":"migration_from_base_and_back_lifecycle_2","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5282026-09-04T01:12:45.380Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.334440756Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5292026-09-04T01:12:45.380Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.334562145Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5302026-09-04T01:12:45.405Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.364862861Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":30,"vm":"migration_from_base_and_back_lifecycle_2","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5312026-09-04T01:12:45.405Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.365036989Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5322026-09-04T01:12:45.405Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.365257766Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5332026-09-04T01:12:45.405Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.365464386Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":19232}
5342026-09-04T01:12:45.405Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.365850144Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5352026-09-04T01:12:45.405Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.366003202Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5362026-09-04T01:12:45.405Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.367030982Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5372026-09-04T01:12:45.662Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.639819472Z","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":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5382026-09-04T01:12:45.744Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.721571811Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5392026-09-04T01:12:45.744Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.721665017Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-ceda6118-c467-4466-a0eb-b1351e522518\"]","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5402026-09-04T01:12:45.771Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.748825127Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5412026-09-04T01:12:45.795Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.748891422Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-19b1116f-dd82-4d4e-95b9-6e2863089f93\"]","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5422026-09-04T01:12:45.795Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.768976084Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":403,"vm":"migration_from_base_and_back_lifecycle_2","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5432026-09-04T01:12:45.795Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.769248581Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":403}
5442026-09-04T01:12:45.795Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.769372348Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5452026-09-04T01:12:45.795Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.769351487Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","vm_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":4639,"vm":"migration_from_base_and_back_lifecycle_2","target_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5462026-09-04T01:12:45.796Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.769422956Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5472026-09-04T01:12:45.796Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.769477209Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","target_id":"e0407416-9b32-470c-b5a5-2879b1befd4d","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":4639,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"2aac2086-b6bc-4efa-bab7-25c130ebdb3a"}
5482026-09-04T01:12:45.796Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.769571427Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":20503,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5492026-09-04T01:12:45.796Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 92.42s
5502026-09-04T01:12:45.796Z
5512026-09-04T01:12:45.796Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-04T01:12:45.771238491Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5522026-09-04T01:12:45.913Z
5532026-09-04T01:12:45.937Zreal 1:37.046899397
5542026-09-04T01:12:45.938Zuser 50.956433133
5552026-09-04T01:12:45.938Zsys 21.744794281
5562026-09-04T01:12:45.938Ztrap 0.007369434
5572026-09-04T01:12:45.938Ztflt 0.005557026
5582026-09-04T01:12:45.938Zdflt 0.001791432
5592026-09-04T01:12:45.938Zkflt 0.000000000
5602026-09-04T01:12:45.938Zlock 3:44:48.249334012
5612026-09-04T01:12:45.938Zslp 4:14.977241812
5622026-09-04T01:12:45.938Zlat 2.318626248
5632026-09-04T01:12:45.938Zstop 45.855183267
5642026-09-04T01:12:45.938Z+ failcount=0
5652026-09-04T01:12:45.938Z+ set -e
5662026-09-04T01:12:45.938Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5672026-09-04T01:12:45.963ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5682026-09-04T01:12:45.963Za ./ 0K
5692026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::serial_history/ 0K
5702026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 158K
5712026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5722026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5732026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 164K
5742026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5752026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5762026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 158K
5772026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5782026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5792026-09-04T01:12:45.963Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 164K
5802026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5812026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5822026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 158K
5832026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5842026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5852026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 269K
5862026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5872026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 269K
5882026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5892026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 164K
5902026-09-04T01:12:45.964Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5912026-09-04T01:12:45.964Z+ exitcode=0
5922026-09-04T01:12:45.964Z+ '[' 0 -eq 0 ']'
5932026-09-04T01:12:45.964Z+ echo
5942026-09-04T01:12:45.964Z
5952026-09-04T01:12:45.964Z+ echo 'ALL TESTS PASSED'
5962026-09-04T01:12:45.964ZALL TESTS PASSED
5972026-09-04T01:12:45.964Z+ echo
5982026-09-04T01:12:45.964Z
5992026-09-04T01:12:45.964Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6002026-09-04T01:12:45.964Z+ read
6012026-09-04T01:12:45.964Z+ exit 0
6022026-09-04T01:12:45.964Zprocess exited: duration 161695 ms, exit code 0
 
6032026-09-04T01:12:46.017Zfound 2 output files
6042026-09-04T01:12:46.017Zuploading: /tmp/phd-runner.log (184352 bytes)
6052026-09-04T01:12:47.162Zuploaded: /tmp/phd-runner.log
6062026-09-04T01:12:47.186Zuploading: /tmp/phd-tmp-files.tar.gz (133206 bytes)
6072026-09-04T01:12:48.345Zuploaded: /tmp/phd-tmp-files.tar.gz