01KV6QD59NX7W16HSYN8921Z95: 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: 01KV6QDHVZZ5CJXMG2FB85TBD9

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-06-15T22:57:25.274Zjob dependencies complete; ready to run (waiting for 11 m 11 s)
22026-06-15T23:05:29.726Zjob assigned to worker 01KV6R22NRRFAAM8T1S16B78MZ [factory edgar, gimlet/BRM42220010/1114] (queued for 8 m 4 s)
32026-06-15T23:05:30.192Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-06-15T23:05:30.219Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-06-15T23:05:30.219Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-06-15T23:05:30.264Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-06-15T23:05:30.264Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-06-15T23:05:38.108Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-06-15T23:05:38.108Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-06-15T23:05:38.156Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-06-15T23:05:38.156Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-06-15T23:05:48.786Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-06-15T23:05:48.786Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-06-15T23:05:57.758Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-06-15T23:05:57.758Zstarting task 0: "setup"
162026-06-15T23:05:57.783Z++ uname -s
172026-06-15T23:05:57.783Z+ kern=SunOS
182026-06-15T23:05:57.783Z+ build_user=build
192026-06-15T23:05:57.783Z+ build_uid=12345
202026-06-15T23:05:57.783Z+ work_dir=/work
212026-06-15T23:05:57.783Z+ input_dir=/input
222026-06-15T23:05:57.783Z+ [[ 0 == 12345 ]]
232026-06-15T23:05:57.783Z+ case "$kern" in
242026-06-15T23:05:57.783Z+ groupadd -g 12345 build
252026-06-15T23:05:57.809Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-06-15T23:05:59.794Z+ zfs create -o mountpoint=/work rpool/work
272026-06-15T23:05:59.824Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-06-15T23:05:59.849Z+ home_fs=
292026-06-15T23:05:59.849Z+ [[ '' == autofs ]]
302026-06-15T23:05:59.849Z+ mkdir -p /home/build
312026-06-15T23:05:59.849Z+ chown build:build /home/build /work
322026-06-15T23:06:01.838Z+ chmod 0700 /home/build /work
332026-06-15T23:06:01.862Zprocess exited: duration 4084 ms, exit code 0
 
342026-06-15T23:06:01.911Zstarting task 1: "authentication"
352026-06-15T23:06:01.980Zprocess exited: duration 67 ms, exit code 0
 
362026-06-15T23:06:02.029Zstarting task 2: "build"
372026-06-15T23:06:02.058Z+ indir=/input
382026-06-15T23:06:02.058Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-06-15T23:06:02.058Z+ phddir=/work/phd-test
402026-06-15T23:06:02.058Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-06-15T23:06:02.082Z++ pilot local disk list -H -o type,disk
422026-06-15T23:06:02.083Z++ grep -v M.2
432026-06-15T23:06:02.083Z++ cut -f 2
442026-06-15T23:06:02.132Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
452026-06-15T23:06:02.407Z+ artifactdir=/phd-artifacts
462026-06-15T23:06:02.407Z+ banner Inputs
472026-06-15T23:06:02.433Z ###
482026-06-15T23:06:02.433Z # # # ##### # # ##### ####
492026-06-15T23:06:02.433Z # ## # # # # # # #
502026-06-15T23:06:02.433Z # # # # # # # # # ####
512026-06-15T23:06:02.433Z # # # # ##### # # # #
522026-06-15T23:06:02.433Z # # ## # # # # # #
532026-06-15T23:06:02.433Z ### # # # #### # ####
542026-06-15T23:06:02.433Z
552026-06-15T23:06:02.433Z+ find /input -ls
562026-06-15T23:06:02.433Z 34 1 drwxr-xr-x 3 root root 3 Jun 15 23:05 /input
572026-06-15T23:06:02.433Z 2 1 drwxr-xr-x 3 root root 3 Jun 15 23:05 /input/phd-build
582026-06-15T23:06:02.433Z 3 2 drwxr-xr-x 2 root root 8 Jun 15 23:05 /input/phd-build/out
592026-06-15T23:06:02.433Z 257 161115 -rw-r--r-- 1 root root 164935821 Jun 15 23:05 /input/phd-build/out/phd-runner.tar.gz
602026-06-15T23:06:02.433Z 640 186465 -rw-r--r-- 1 root root 190946692 Jun 15 23:05 /input/phd-build/out/propolis-tests-debug.tar.gz
612026-06-15T23:06:02.433Z 256 1 -rw-r--r-- 1 root root 65 Jun 15 23:05 /input/phd-build/out/phd-runner.sha256.txt
622026-06-15T23:06:02.433Z 384 1 -rw-r--r-- 1 root root 65 Jun 15 23:05 /input/phd-build/out/propolis-server-debug.sha256.txt
632026-06-15T23:06:02.433Z 128 2 -rw-r--r-- 1 root root 2573 Jun 15 23:05 /input/phd-build/out/phd-run-with-args.sh
642026-06-15T23:06:02.433Z 512 223694 -rw-r--r-- 1 root root 229140348 Jun 15 23:05 /input/phd-build/out/propolis-server-debug.tar.gz
652026-06-15T23:06:02.434Z+ rm -rf /work/phd-test
662026-06-15T23:06:02.434Z+ mkdir /work/phd-test
672026-06-15T23:06:02.434Z+ for p in $indir/$indir_suffix
682026-06-15T23:06:02.434Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-06-15T23:06:06.725ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-06-15T23:06:06.725Zx phd-runner, 602775056 bytes, 1177296 tape blocks
712026-06-15T23:06:06.725Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-06-15T23:06:06.750Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-06-15T23:06:10.880Z+ for f in $(tar tf "$p")
742026-06-15T23:06:10.881Z+ chmod +x /work/phd-test/phd-runner
752026-06-15T23:06:10.905Z+ for f in $(tar tf "$p")
762026-06-15T23:06:10.905Z+ chmod +x /work/phd-test/artifacts.toml
772026-06-15T23:06:10.905Z+ for p in $indir/$indir_suffix
782026-06-15T23:06:10.905Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-06-15T23:06:24.104ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-06-15T23:06:24.104Zx propolis-server, 875950896 bytes, 1710842 tape blocks
812026-06-15T23:06:24.129Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-06-15T23:06:29.968Z+ for f in $(tar tf "$p")
832026-06-15T23:06:29.968Z+ chmod +x /work/phd-test/propolis-server
842026-06-15T23:06:29.993Z+ for p in $indir/$indir_suffix
852026-06-15T23:06:29.993Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-06-15T23:06:41.558ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-06-15T23:06:41.558Zx target/debug/deps/propolis-3c9f0055fc696694, 730060376 bytes, 1425900 tape blocks
882026-06-15T23:06:41.583Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-06-15T23:06:46.423Z+ for f in $(tar tf "$p")
902026-06-15T23:06:46.423Z+ chmod +x /work/phd-test/target/debug/deps/propolis-3c9f0055fc696694
912026-06-15T23:06:46.448Z+ ls /work/phd-test
922026-06-15T23:06:46.448Zartifacts.toml
932026-06-15T23:06:46.448Zphd-runner
942026-06-15T23:06:46.448Zpropolis-server
952026-06-15T23:06:46.448Ztarget
962026-06-15T23:06:46.448Z+ banner Setup
972026-06-15T23:06:46.448Z #####
982026-06-15T23:06:46.448Z# # ###### ##### # # #####
992026-06-15T23:06:46.448Z# # # # # # #
1002026-06-15T23:06:46.449Z ##### ##### # # # # #
1012026-06-15T23:06:46.449Z # # # # # #####
1022026-06-15T23:06:46.449Z# # # # # # #
1032026-06-15T23:06:46.449Z ##### ###### # #### #
1042026-06-15T23:06:46.449Z
1052026-06-15T23:06:46.449Z+ tmpdir=/tmp/propolis-phd
1062026-06-15T23:06:46.449Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-06-15T23:06:46.449Z+ mkdir /tmp/propolis-phd
1082026-06-15T23:06:46.449Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-06-15T23:06:46.922Z+ banner Tests
1102026-06-15T23:06:46.947Z#######
1112026-06-15T23:06:46.947Z # ###### #### ##### ####
1122026-06-15T23:06:46.947Z # # # # #
1132026-06-15T23:06:46.947Z # ##### #### # ####
1142026-06-15T23:06:46.947Z # # # # #
1152026-06-15T23:06:46.947Z # # # # # # #
1162026-06-15T23:06:46.947Z # ###### #### # ####
1172026-06-15T23:06:46.947Z
1182026-06-15T23:06:46.947Z+ runner=/work/phd-test/phd-runner
1192026-06-15T23:06:46.947Z+ artifacts=/work/phd-test/artifacts.toml
1202026-06-15T23:06:46.947Z+ propolis=/work/phd-test/propolis-server
1212026-06-15T23:06:46.947Z+ ls /work/phd-test/phd-runner
1222026-06-15T23:06:46.947Z/work/phd-test/phd-runner
1232026-06-15T23:06:46.947Z+ ls /work/phd-test/artifacts.toml
1242026-06-15T23:06:46.947Z/work/phd-test/artifacts.toml
1252026-06-15T23:06:46.947Z+ ls /work/phd-test/propolis-server
1262026-06-15T23:06:46.947Z/work/phd-test/propolis-server
1272026-06-15T23:06:46.947Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-06-15T23:06:46.947Z+ set +e
1292026-06-15T23:06:46.947Z+ RUST_BACKTRACE=1
1302026-06-15T23:06:46.947Z+ RUST_LOG=info,phd=debug
1312026-06-15T23:06:46.947Z+ 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-06-15T23:06:46.947Z+ tee /tmp/phd-runner.log
1332026-06-15T23:06:47.143Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:47.116822771Z","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-06-15T23:06:47.168Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:47.145945978Z","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: 227, tv_nsec: 846423846 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-06-15T23:06:47.168Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:47.146930744Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-06-15T23:06:47.168Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:47.148822684Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"e7af674f27ed04ce27739edee96829f7d7d5e6c0"}
1372026-06-15T23:06:47.193Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:47.152266814Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/e7af674f27ed04ce27739edee96829f7d7d5e6c0/crucible-nightly.sha256.txt","timeout":"600s"}
1382026-06-15T23:06:47.357Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:47.338949392Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-06-15T23:06:47.901Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:47.882622954Z","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/fa3972150b7dc4a329174a3157ea2901c90bcf7d/propolis-server.sha256.txt"}
1402026-06-15T23:06:48.056Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.037362796Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-06-15T23:06:48.081Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.03993687Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-06-15T23:06:48.081Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.041533031Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-06-15T23:06:48.081Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.041579278Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-06-15T23:06:48.081Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.041608624Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-06-15T23:06:48.081Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.041640374Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-06-15T23:06:48.081Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.042831508Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1472026-06-15T23:06:48.081Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.047209696Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1482026-06-15T23:06:48.081Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.04859117Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1492026-06-15T23:06:48.615Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:48.596640856Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1502026-06-15T23:06:48.642Z{"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":830,"time":"2026-06-15T23:06:48.610812401Z","target":"phd_framework::artifacts::store","line":614,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1512026-06-15T23:06:55.325Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.303696535Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1522026-06-15T23:06:55.349Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.304130065Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1532026-06-15T23:06:55.350Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.319317744Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2.08M 25.3T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1542026-06-15T23:06:55.350Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.322509306Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-e32fee2c-3c02-4385-9c53-65f4b95a2db1\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1552026-06-15T23:06:55.374Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.345430103Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-e32fee2c-3c02-4385-9c53-65f4b95a2db1\", \"phd-artifacts/phd-clone-6e6e2dc8-91d3-4617-a4e2-153dc7066486\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1562026-06-15T23:06:55.399Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.363960951Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-6e6e2dc8-91d3-4617-a4e2-153dc7066486\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1572026-06-15T23:06:55.399Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.373860842Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-6e6e2dc8-91d3-4617-a4e2-153dc7066486 0B 25.3T 48.9M /phd-artifacts/phd-clone-6e6e2dc8-91d3-4617-a4e2-153dc7066486\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1582026-06-15T23:06:55.399Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.377961354Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1592026-06-15T23:06:55.399Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.378061804Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1602026-06-15T23:06:55.399Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.378141605Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/f869dc8b99e697f734fc91d3871e30ba905e761bf3bf18e1874243d645cb6d4c/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1612026-06-15T23:06:55.399Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:06:55.378221687Z","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/fa3972150b7dc4a329174a3157ea2901c90bcf7d/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1622026-06-15T23:07:08.489Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:08.464427696Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/f869dc8b99e697f734fc91d3871e30ba905e761bf3bf18e1874243d645cb6d4c/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632026-06-15T23:07:08.489Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:08.464509681Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1642026-06-15T23:07:30.310Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:30.279351116Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/f869dc8b99e697f734fc91d3871e30ba905e761bf3bf18e1874243d645cb6d4c/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-06-15T23:07:30.310Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:30.279478276Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1662026-06-15T23:07:30.471Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 835","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:30.440914701Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1672026-06-15T23:07:30.495Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:30.457501526Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1682026-06-15T23:07:30.520Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:30.468478413Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1692026-06-15T23:07:30.520Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:30.472421376Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":35102,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1702026-06-15T23:07:31.198Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.167638806Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-06-15T23:07:31.246Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.168504276Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 28951596-eebb-4a96-8f53-992010631318, name: \"phd-vm-28951596-eebb-4a96-8f53-992010631318\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: a504cf4e-c583-45a1-b811-4d7935d9eb09, project_id: 95c7d5dd-53d8-4b5a-aa81-2e1aa42bc7ce, sled_id: 5d19e0df-b155-4e6d-a2dd-5389588f1d2e, sled_serial: \"5d19e0df-b155-4e6d-a2dd-5389588f1d2e\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1722026-06-15T23:07:31.246Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.168704966Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1732026-06-15T23:07:31.246Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.169329057Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1742026-06-15T23:07:31.246Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.170879261Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":2,"vm":"migration_from_base"}
1752026-06-15T23:07:31.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.171303414Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1762026-06-15T23:07:31.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.17138584Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1772026-06-15T23:07:31.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.171442827Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1782026-06-15T23:07:31.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.171488945Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1792026-06-15T23:07:31.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:31.172069012Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1802026-06-15T23:07:35.748Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.716362235Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":4545,"vm":"migration_from_base"}
1812026-06-15T23:07:35.749Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.716453758Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1822026-06-15T23:07:35.774Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.71763826Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1832026-06-15T23:07:35.774Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.717703333Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1842026-06-15T23:07:35.774Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.717756514Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1852026-06-15T23:07:35.799Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.744870064Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":27,"vm":"migration_from_base"}
1862026-06-15T23:07:35.799Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.745018064Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1872026-06-15T23:07:35.799Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.745466135Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1882026-06-15T23:07:35.800Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.745579489Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1892026-06-15T23:07:35.800Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.745673296Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1902026-06-15T23:07:35.824Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.777158049Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":31,"vm":"migration_from_base"}
1912026-06-15T23:07:35.824Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.777273427Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1922026-06-15T23:07:35.825Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.777346896Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4606,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1932026-06-15T23:07:35.825Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.778332932Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1942026-06-15T23:07:35.825Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.778803545Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1952026-06-15T23:07:35.825Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.788763937Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":9,"vm":"migration_from_base"}
1962026-06-15T23:07:35.825Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.788886579Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1972026-06-15T23:07:35.825Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.788935512Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1982026-06-15T23:07:35.854Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.82232968Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":33,"vm":"migration_from_base"}
1992026-06-15T23:07:35.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.823188014Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2002026-06-15T23:07:35.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.823237137Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2012026-06-15T23:07:35.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.833895482Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":10,"vm":"migration_from_base"}
2022026-06-15T23:07:35.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.834133412Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2032026-06-15T23:07:35.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.834180151Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2042026-06-15T23:07:35.904Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.867473939Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":33,"vm":"migration_from_base"}
2052026-06-15T23:07:35.904Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.867800126Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2062026-06-15T23:07:35.904Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.867904474Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2072026-06-15T23:07:35.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.878833619Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":10,"vm":"migration_from_base"}
2082026-06-15T23:07:35.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.879118779Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2092026-06-15T23:07:35.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.879207276Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2102026-06-15T23:07:35.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.91111932Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":31,"vm":"migration_from_base"}
2112026-06-15T23:07:35.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.911434015Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2122026-06-15T23:07:35.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.91154726Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2132026-06-15T23:07:35.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.922134971Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":10,"vm":"migration_from_base"}
2142026-06-15T23:07:35.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.922360578Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2152026-06-15T23:07:35.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.922425571Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2162026-06-15T23:07:35.988Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.956301451Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":33,"vm":"migration_from_base"}
2172026-06-15T23:07:36.014Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.956615836Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2182026-06-15T23:07:36.014Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.956720594Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2192026-06-15T23:07:36.014Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.967369128Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":10,"vm":"migration_from_base"}
2202026-06-15T23:07:36.014Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.967600528Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2212026-06-15T23:07:36.014Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:35.967696159Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2222026-06-15T23:07:36.039Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.00104537Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":33,"vm":"migration_from_base"}
2232026-06-15T23:07:36.039Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.001316453Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2242026-06-15T23:07:36.039Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.001416002Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2252026-06-15T23:07:36.064Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.012151052Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":10,"vm":"migration_from_base"}
2262026-06-15T23:07:36.065Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.012384273Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2272026-06-15T23:07:36.065Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.012469855Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2282026-06-15T23:07:36.090Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.045356102Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":32,"vm":"migration_from_base"}
2292026-06-15T23:07:36.090Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.046372516Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2302026-06-15T23:07:36.090Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.046523391Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2312026-06-15T23:07:36.090Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.04662331Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2322026-06-15T23:07:36.090Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.046723139Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","sha256":"None","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2332026-06-15T23:07:36.090Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.046778504Z","target":"phd_framework::artifacts::store","line":69,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2342026-06-15T23:07:36.090Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.046830492Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2352026-06-15T23:07:36.090Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.046892189Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2362026-06-15T23:07:36.124Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 836","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.09239119Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2372026-06-15T23:07:36.149Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.105299282Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":58,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2382026-06-15T23:07:36.149Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.10538271Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"28951596-eebb-4a96-8f53-992010631318"}
2392026-06-15T23:07:36.149Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.10544624Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"08ccb5d7-8dfc-4eb1-9817-8ab969168eff","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"28951596-eebb-4a96-8f53-992010631318"}
2402026-06-15T23:07:36.149Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.10550401Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base_lifecycle_0","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7"}
2412026-06-15T23:07:36.149Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.106054972Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base_lifecycle_0","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7"}
2422026-06-15T23:07:36.831Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.798767152Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c7867a4f-7a9c-47ed-88ad-598669b19aa7, name: \"phd-vm-c7867a4f-7a9c-47ed-88ad-598669b19aa7\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: a504cf4e-c583-45a1-b811-4d7935d9eb09, project_id: 95c7d5dd-53d8-4b5a-aa81-2e1aa42bc7ce, sled_id: 2dc31de8-d38a-4648-80e8-8d08e3e9ca7b, sled_serial: \"2dc31de8-d38a-4648-80e8-8d08e3e9ca7b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base_lifecycle_0","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7"}
2432026-06-15T23:07:36.856Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:36.799435907Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","migration_id":"08ccb5d7-8dfc-4eb1-9817-8ab969168eff","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"28951596-eebb-4a96-8f53-992010631318"}
2442026-06-15T23:07:39.764Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:39.731622591Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
2452026-06-15T23:07:42.808Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.755494747Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"28951596-eebb-4a96-8f53-992010631318"}
2462026-06-15T23:07:42.808Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.755581602Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","migration_id":"08ccb5d7-8dfc-4eb1-9817-8ab969168eff","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":5956}
2472026-06-15T23:07:42.833Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.757652321Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2482026-06-15T23:07:42.833Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.759116171Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2492026-06-15T23:07:42.833Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.759182857Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2502026-06-15T23:07:42.833Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.761142836Z","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":"28951596-eebb-4a96-8f53-992010631318","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2512026-06-15T23:07:42.884Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.851722185Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":92,"vm":"migration_from_base"}
2522026-06-15T23:07:42.912Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.851954004Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":12396,"vm":"migration_from_base"}
2532026-06-15T23:07:42.912Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.852092947Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","elapsed_milliseconds":92,"vm":"migration_from_base_lifecycle_0"}
2542026-06-15T23:07:42.912Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.852391362Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-06-15T23:07:42.912Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.852504245Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-06-15T23:07:42.937Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.885286876Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","elapsed_milliseconds":32,"vm":"migration_from_base_lifecycle_0"}
2572026-06-15T23:07:42.937Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.885469462Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2582026-06-15T23:07:42.937Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.885779699Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2592026-06-15T23:07:42.937Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.886466358Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2602026-06-15T23:07:42.937Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.88656218Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2612026-06-15T23:07:42.937Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.886807895Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":11720}
2622026-06-15T23:07:42.937Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:42.887477231Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2632026-06-15T23:07:43.513Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.48004635Z","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":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2642026-06-15T23:07:43.600Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.567082601Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2652026-06-15T23:07:43.600Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.567181779Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-6e6e2dc8-91d3-4617-a4e2-153dc7066486\"]","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2662026-06-15T23:07:43.626Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.593644528Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2672026-06-15T23:07:43.626Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.59370916Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-e32fee2c-3c02-4385-9c53-65f4b95a2db1\"]","verb":"destroy","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2682026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.611927324Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","elapsed_milliseconds":726,"vm":"migration_from_base_lifecycle_0"}
2692026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.612625515Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":7508,"vm_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","source_id":"28951596-eebb-4a96-8f53-992010631318"}
2702026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.612687883Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c7867a4f-7a9c-47ed-88ad-598669b19aa7","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"28951596-eebb-4a96-8f53-992010631318","elapsed_milliseconds":7508}
2712026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.612734231Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":55580,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.613202617Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":726}
2732026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.613302306Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2742026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.613345378Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2752026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.613382257Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2762026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.613641728Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2772026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.613787033Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
2782026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.61384853Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::serial_history"}
2792026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.613920446Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::serial_history"}
2802026-06-15T23:07:43.651Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.613992292Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::serial_history"}
2812026-06-15T23:07:43.676Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.624268441Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.08G 25.3T 1.08G /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2822026-06-15T23:07:43.676Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.624395923Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-d616b90e-f34f-49a9-888e-4ffee778c4d8\"]","path":"phd_tests::migrate::from_base::serial_history"}
2832026-06-15T23:07:43.701Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.645053333Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-d616b90e-f34f-49a9-888e-4ffee778c4d8\", \"phd-artifacts/phd-clone-fee27b28-0b26-4647-8f4b-5c834918f610\"]","path":"phd_tests::migrate::from_base::serial_history"}
2842026-06-15T23:07:43.701Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.662407872Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-fee27b28-0b26-4647-8f4b-5c834918f610\"]","path":"phd_tests::migrate::from_base::serial_history"}
2852026-06-15T23:07:43.726Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.674049608Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-fee27b28-0b26-4647-8f4b-5c834918f610 0B 25.3T 1.08G /phd-artifacts/phd-clone-fee27b28-0b26-4647-8f4b-5c834918f610\n","path":"phd_tests::migrate::from_base::serial_history"}
2862026-06-15T23:07:43.726Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.674843821Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2872026-06-15T23:07:43.726Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.674910968Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
2882026-06-15T23:07:43.726Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.674987974Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/f869dc8b99e697f734fc91d3871e30ba905e761bf3bf18e1874243d645cb6d4c/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2892026-06-15T23:07:43.726Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.675048027Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/f869dc8b99e697f734fc91d3871e30ba905e761bf3bf18e1874243d645cb6d4c/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
2902026-06-15T23:07:43.726Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.675124462Z","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"}
2912026-06-15T23:07:43.756Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 845","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.723472935Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
2922026-06-15T23:07:43.781Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.737673905Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":62}
2932026-06-15T23:07:43.781Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.737778703Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2942026-06-15T23:07:43.781Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:43.738466324Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2952026-06-15T23:07:44.697Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.600119463Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2962026-06-15T23:07:44.745Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.60138084Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 7256d4b9-4412-4455-9d87-b4f7b483b9fa, name: \"phd-vm-7256d4b9-4412-4455-9d87-b4f7b483b9fa\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 9d411ddb-f7e3-4c3f-8c33-4c35ad0ace39, project_id: 734862e5-3dc7-478f-b872-cd5ab866d34a, sled_id: 12295ada-ee4d-4f9f-82c9-45994cfcbe7b, sled_serial: \"12295ada-ee4d-4f9f-82c9-45994cfcbe7b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2972026-06-15T23:07:44.745Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.601572823Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2982026-06-15T23:07:44.745Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.60162932Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2992026-06-15T23:07:44.745Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.602564602Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3002026-06-15T23:07:44.745Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.602644072Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3012026-06-15T23:07:44.745Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.602699457Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_serial_history_base","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history"}
3022026-06-15T23:07:44.745Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.602744312Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
3032026-06-15T23:07:44.745Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.602784969Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3042026-06-15T23:07:44.745Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:44.602830475Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3052026-06-15T23:07:49.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.212452631Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4610,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3062026-06-15T23:07:49.246Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.212544064Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
3072026-06-15T23:07:49.271Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.212725728Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3082026-06-15T23:07:49.271Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.212778328Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3092026-06-15T23:07:49.271Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.212826218Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3102026-06-15T23:07:49.271Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.231387732Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3112026-06-15T23:07:49.271Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.231544268Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3122026-06-15T23:07:49.271Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.231756921Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3132026-06-15T23:07:49.271Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.23180936Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3142026-06-15T23:07:49.271Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.231854475Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3152026-06-15T23:07:49.298Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.263469637Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3162026-06-15T23:07:49.298Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.263591648Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3172026-06-15T23:07:49.298Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.263664546Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4661}
3182026-06-15T23:07:49.323Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.263797908Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3192026-06-15T23:07:49.323Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.263848143Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3202026-06-15T23:07:49.323Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.274369358Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3212026-06-15T23:07:49.323Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.274610465Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3222026-06-15T23:07:49.323Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.274706166Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3232026-06-15T23:07:49.348Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.307382634Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3242026-06-15T23:07:49.348Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.307632338Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3252026-06-15T23:07:49.348Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.307731366Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3262026-06-15T23:07:49.373Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.318266846Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3272026-06-15T23:07:49.373Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.318507451Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3282026-06-15T23:07:49.373Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.318604635Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3292026-06-15T23:07:49.398Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.351785821Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3302026-06-15T23:07:49.398Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.358459863Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3312026-06-15T23:07:49.398Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.358582736Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3322026-06-15T23:07:49.398Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.358630997Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
3332026-06-15T23:07:49.398Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.358691101Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
3342026-06-15T23:07:49.398Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.358742528Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history"}
3352026-06-15T23:07:49.398Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.358811378Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
3362026-06-15T23:07:49.436Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 846","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.402072602Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
3372026-06-15T23:07:49.461Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.415753048Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":57}
3382026-06-15T23:07:49.461Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.415839782Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base"}
3392026-06-15T23:07:49.461Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.415910416Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"e3ae3e31-93f1-4b68-9c05-5f636a79fff1","timeout_duration":"45s","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base"}
3402026-06-15T23:07:49.461Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.415973215Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base"}
3412026-06-15T23:07:49.461Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:49.416493269Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","vm":"migration_serial_history_base_lifecycle_0","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base"}
3422026-06-15T23:07:50.307Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:50.272310792Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 51e5bb4d-d8ea-4cac-851e-7f7753968eed, name: \"phd-vm-51e5bb4d-d8ea-4cac-851e-7f7753968eed\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 9d411ddb-f7e3-4c3f-8c33-4c35ad0ace39, project_id: 734862e5-3dc7-478f-b872-cd5ab866d34a, sled_id: 029649dd-cd91-49ba-8fce-f0787cd244e6, sled_serial: \"029649dd-cd91-49ba-8fce-f0787cd244e6\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm":"migration_serial_history_base_lifecycle_0","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base"}
3432026-06-15T23:07:50.307Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:50.272514508Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"e3ae3e31-93f1-4b68-9c05-5f636a79fff1","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base"}
3442026-06-15T23:07:53.237Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:53.202632104Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7756}}"}
3452026-06-15T23:07:55.240Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.204898654Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base"}
3462026-06-15T23:07:55.240Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.205034451Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"e3ae3e31-93f1-4b68-9c05-5f636a79fff1","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","elapsed_milliseconds":4933,"target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base"}
3472026-06-15T23:07:55.265Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.207617371Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3482026-06-15T23:07:55.266Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.209402339Z","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":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3492026-06-15T23:07:55.336Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.301059187Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":93,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3502026-06-15T23:07:55.361Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.301225673Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11565,"vm_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3512026-06-15T23:07:55.361Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.304022385Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3522026-06-15T23:07:55.361Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.304225159Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3532026-06-15T23:07:55.361Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.304350927Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10705}
3542026-06-15T23:07:55.361Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.304398397Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3552026-06-15T23:07:55.361Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.304525277Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3562026-06-15T23:07:55.361Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.305822302Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3572026-06-15T23:07:56.011Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:55.975670826Z","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":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3582026-06-15T23:07:56.097Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.061850556Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3592026-06-15T23:07:56.097Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.061954222Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-fee27b28-0b26-4647-8f4b-5c834918f610\"]","verb":"destroy","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3602026-06-15T23:07:56.123Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.088207743Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3612026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.08830639Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-d616b90e-f34f-49a9-888e-4ffee778c4d8\"]","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3622026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.10645917Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":802,"vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3632026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.106634782Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","elapsed_milliseconds":6691,"target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base","vm_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed"}
3642026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.106698413Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"7256d4b9-4412-4455-9d87-b4f7b483b9fa","elapsed_milliseconds":6691,"target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target_id":"51e5bb4d-d8ea-4cac-851e-7f7753968eed","source":"migration_serial_history_base"}
3652026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.106747516Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":12494}
3662026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.106741274Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":802}
3672026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.106860229Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3682026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.106907779Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3692026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.106958405Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3702026-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.107123227Z","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-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.107224719Z","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-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.107288179Z","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-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.107351989Z","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-06-15T23:07:56.148Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.107418565Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3752026-06-15T23:07:56.173Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.11910202Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.08G 25.3T 1.08G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-06-15T23:07:56.173Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.119200397Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-dd649b55-880e-421b-a28c-6b0fdcc93f20\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-06-15T23:07:56.173Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.137986996Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-dd649b55-880e-421b-a28c-6b0fdcc93f20\", \"phd-artifacts/phd-clone-184f1c45-8d7a-4920-bb04-9141e22eadd7\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-06-15T23:07:56.198Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.157841156Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-184f1c45-8d7a-4920-bb04-9141e22eadd7\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-06-15T23:07:56.228Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.169422666Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-184f1c45-8d7a-4920-bb04-9141e22eadd7 0B 25.3T 1.08G /phd-artifacts/phd-clone-184f1c45-8d7a-4920-bb04-9141e22eadd7\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-06-15T23:07:56.228Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.170067999Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3812026-06-15T23:07:56.228Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.170132862Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-06-15T23:07:56.228Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.170210118Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/f869dc8b99e697f734fc91d3871e30ba905e761bf3bf18e1874243d645cb6d4c/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-06-15T23:07:56.228Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.170272366Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/f869dc8b99e697f734fc91d3871e30ba905e761bf3bf18e1874243d645cb6d4c/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-06-15T23:07:56.228Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.170358148Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-06-15T23:07:56.256Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 855","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.220804993Z","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-06-15T23:07:56.280Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.237527446Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":67}
3872026-06-15T23:07:56.281Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.23763016Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
3882026-06-15T23:07:56.281Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.238325436Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
3892026-06-15T23:07:56.881Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.844863195Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3902026-06-15T23:07:56.928Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.845768528Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c438cd50-95ed-4932-a8ce-581252ba0f10, name: \"phd-vm-c438cd50-95ed-4932-a8ce-581252ba0f10\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 416228b7-5133-4131-b843-f189d325008f, project_id: 9324f57c-e9ec-4dbf-8be4-35ebb626d05b, sled_id: 5e1005bb-5624-4a64-918a-eadb48ae156e, sled_serial: \"5e1005bb-5624-4a64-918a-eadb48ae156e\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
3912026-06-15T23:07:56.928Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.845985178Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
3922026-06-15T23:07:56.928Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.846037156Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
3932026-06-15T23:07:56.928Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.847049883Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":1,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3942026-06-15T23:07:56.928Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.847132359Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3952026-06-15T23:07:56.928Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.847188966Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-06-15T23:07:56.928Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.847235033Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972026-06-15T23:07:56.928Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.847277203Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
3982026-06-15T23:07:56.928Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:07:56.847324983Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
3992026-06-15T23:08:01.453Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.416336503Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4569,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4002026-06-15T23:08:01.453Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.416427766Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012026-06-15T23:08:01.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.41660447Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4022026-06-15T23:08:01.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.416659354Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4032026-06-15T23:08:01.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.416698177Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4042026-06-15T23:08:01.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.435056446Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4052026-06-15T23:08:01.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.435152107Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4062026-06-15T23:08:01.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.435334502Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4072026-06-15T23:08:01.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.435398714Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4082026-06-15T23:08:01.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.43545493Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4092026-06-15T23:08:01.505Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.468690939Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4102026-06-15T23:08:01.505Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.468838489Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4112026-06-15T23:08:01.505Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.468912839Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4622}
4122026-06-15T23:08:01.530Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.469155639Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4132026-06-15T23:08:01.530Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.469206395Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4142026-06-15T23:08:01.530Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.479983763Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4152026-06-15T23:08:01.530Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.480225991Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4162026-06-15T23:08:01.530Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.480322143Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4172026-06-15T23:08:01.555Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.513115064Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4182026-06-15T23:08:01.555Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.513356771Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4192026-06-15T23:08:01.555Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.513454907Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4202026-06-15T23:08:01.580Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.523934193Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4212026-06-15T23:08:01.580Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.524174608Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4222026-06-15T23:08:01.580Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.524254269Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4232026-06-15T23:08:01.605Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.557315878Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4242026-06-15T23:08:01.605Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.557562194Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4252026-06-15T23:08:01.605Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.557659317Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4262026-06-15T23:08:01.629Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.568494866Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4272026-06-15T23:08:01.630Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.568886609Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4282026-06-15T23:08:01.630Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.569013289Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4292026-06-15T23:08:01.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.601084211Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4302026-06-15T23:08:01.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.601332811Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4312026-06-15T23:08:01.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.601428052Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4322026-06-15T23:08:01.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.612205752Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4332026-06-15T23:08:01.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.612435136Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4342026-06-15T23:08:01.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.612510409Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4352026-06-15T23:08:01.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.645759412Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4362026-06-15T23:08:01.706Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.646086111Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4372026-06-15T23:08:01.706Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.646203022Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4382026-06-15T23:08:01.706Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.657319434Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4392026-06-15T23:08:01.707Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.657560049Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4402026-06-15T23:08:01.707Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.657665348Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4412026-06-15T23:08:01.731Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.689944825Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4422026-06-15T23:08:01.731Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.690221899Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4432026-06-15T23:08:01.731Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.690323101Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4442026-06-15T23:08:01.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.700910311Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4452026-06-15T23:08:01.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.70115256Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4462026-06-15T23:08:01.756Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.701250375Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4472026-06-15T23:08:01.781Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.734379982Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4482026-06-15T23:08:01.781Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.734618594Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4492026-06-15T23:08:01.781Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.734759561Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-06-15T23:08:01.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.734844061Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-06-15T23:08:01.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.734959088Z","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-06-15T23:08:01.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.735056793Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-06-15T23:08:01.781Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.735180798Z","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_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-06-15T23:08:01.816Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 856","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.779353128Z","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-06-15T23:08:01.840Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.792350219Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":57}
4562026-06-15T23:08:01.840Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.792434578Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back"}
4572026-06-15T23:08:01.841Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.792498128Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"1e2a155d-a3fd-44ec-bf09-02057db51c27","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back"}
4582026-06-15T23:08:01.841Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.792558092Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back"}
4592026-06-15T23:08:01.841Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:01.793084228Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back"}
4602026-06-15T23:08:02.637Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:02.600227309Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 2dce15b6-6a29-4872-a932-01669ec72714, name: \"phd-vm-2dce15b6-6a29-4872-a932-01669ec72714\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 416228b7-5133-4131-b843-f189d325008f, project_id: 9324f57c-e9ec-4dbf-8be4-35ebb626d05b, sled_id: 77d23a3f-b177-4db5-bfc3-9b90e38854bb, sled_serial: \"77d23a3f-b177-4db5-bfc3-9b90e38854bb\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back"}
4612026-06-15T23:08:02.637Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:02.600431075Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","migration_id":"1e2a155d-a3fd-44ec-bf09-02057db51c27","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back"}
4622026-06-15T23:08:05.579Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:05.542224834Z","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-06-15T23:08:06.892Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.853916672Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back"}
4642026-06-15T23:08:06.892Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.854050115Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","migration_id":"1e2a155d-a3fd-44ec-bf09-02057db51c27","elapsed_milliseconds":4254,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back"}
4652026-06-15T23:08:06.917Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.856556047Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4662026-06-15T23:08:06.917Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.856766105Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0"}
4672026-06-15T23:08:06.917Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.856823153Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0"}
4682026-06-15T23:08:06.917Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.857981605Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","vm":"migration_from_base_and_back"}
4692026-06-15T23:08:06.985Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.948046971Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":91,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4702026-06-15T23:08:07.010Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.948260645Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10712,"vm_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4712026-06-15T23:08:07.011Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.948486403Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":91,"vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4722026-06-15T23:08:07.011Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.948770721Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0"}
4732026-06-15T23:08:07.011Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.948839481Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0"}
4742026-06-15T23:08:07.037Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.983171554Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":34,"vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4752026-06-15T23:08:07.037Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.983361423Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__BASE_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762026-06-15T23:08:07.037Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.983517509Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772026-06-15T23:08:07.037Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.983633108Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_1","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-06-15T23:08:07.037Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.98376642Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/f869dc8b99e697f734fc91d3871e30ba905e761bf3bf18e1874243d645cb6d4c/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-06-15T23:08:07.037Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.983870677Z","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:9004","server_path":"\"/phd-artifacts/f869dc8b99e697f734fc91d3871e30ba905e761bf3bf18e1874243d645cb6d4c/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-06-15T23:08:07.037Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:06.983995684Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-06-15T23:08:07.074Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 858","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:07.031314699Z","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-06-15T23:08:07.107Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:07.045530165Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":61}
4832026-06-15T23:08:07.107Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:07.045645975Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0"}
4842026-06-15T23:08:07.107Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:07.045731096Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"48cf6822-1cac-4e3c-9082-a5c42209d50c","timeout_duration":"45s","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0"}
4852026-06-15T23:08:07.107Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:07.045801188Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0"}
4862026-06-15T23:08:07.107Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:07.046410782Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0"}
4872026-06-15T23:08:07.484Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:07.444561016Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 7808537b-bca8-48ad-8ce4-d3e3d05ad3fb, name: \"phd-vm-7808537b-bca8-48ad-8ce4-d3e3d05ad3fb\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 416228b7-5133-4131-b843-f189d325008f, project_id: 9324f57c-e9ec-4dbf-8be4-35ebb626d05b, sled_id: ef962be5-f97f-4271-b2cf-63f4493dd88b, sled_serial: \"ef962be5-f97f-4271-b2cf-63f4493dd88b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0"}
4882026-06-15T23:08:07.484Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:07.44475307Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","migration_id":"48cf6822-1cac-4e3c-9082-a5c42209d50c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0"}
4892026-06-15T23:08:10.427Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.387902966Z","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-06-15T23:08:10.621Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.582362477Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0"}
4912026-06-15T23:08:10.621Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.582423592Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","migration_id":"48cf6822-1cac-4e3c-9082-a5c42209d50c","elapsed_milliseconds":3138,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0"}
4922026-06-15T23:08:10.646Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.584477379Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0"}
4932026-06-15T23:08:10.647Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.584718225Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1"}
4942026-06-15T23:08:10.647Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.584782016Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1"}
4952026-06-15T23:08:10.647Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.586104529Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0"}
4962026-06-15T23:08:10.713Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.674252143Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":89,"vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4972026-06-15T23:08:10.738Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.674503579Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back","elapsed_milliseconds":8883,"vm_id":"2dce15b6-6a29-4872-a932-01669ec72714","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","vm":"migration_from_base_and_back_lifecycle_0"}
4982026-06-15T23:08:10.738Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:10.674599401Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"2dce15b6-6a29-4872-a932-01669ec72714","elapsed_milliseconds":8883,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c438cd50-95ed-4932-a8ce-581252ba0f10","source":"migration_from_base_and_back"}
4992026-06-15T23:08:11.611Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.572086805Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":987,"vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5002026-06-15T23:08:11.637Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.572391664Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1"}
5012026-06-15T23:08:11.637Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.572498206Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1"}
5022026-06-15T23:08:11.664Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.605566826Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5032026-06-15T23:08:11.664Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.605709095Z","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-06-15T23:08:11.664Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.605848118Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5052026-06-15T23:08:11.664Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.605923671Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_2","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-06-15T23:08:11.664Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.605988684Z","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-06-15T23:08:11.665Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.606038669Z","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:9006","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-06-15T23:08:11.665Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.60611304Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-06-15T23:08:11.689Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 860","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.651065807Z","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-06-15T23:08:11.714Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.663754404Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":57}
5112026-06-15T23:08:11.714Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.663834034Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1"}
5122026-06-15T23:08:11.714Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.663904297Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"2fab055a-3b59-475d-9ccc-5bc3e92133d1","timeout_duration":"45s","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1"}
5132026-06-15T23:08:11.714Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.663968028Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1"}
5142026-06-15T23:08:11.714Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:11.664469096Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1"}
5152026-06-15T23:08:12.303Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:12.261966054Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c251693a-54bf-4bc4-a11c-abd984688863, name: \"phd-vm-c251693a-54bf-4bc4-a11c-abd984688863\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 416228b7-5133-4131-b843-f189d325008f, project_id: 9324f57c-e9ec-4dbf-8be4-35ebb626d05b, sled_id: 66cf4357-7bdc-43df-b264-4881b59d3de4, sled_serial: \"66cf4357-7bdc-43df-b264-4881b59d3de4\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1"}
5162026-06-15T23:08:12.303Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:12.26213861Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","migration_id":"2fab055a-3b59-475d-9ccc-5bc3e92133d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1"}
5172026-06-15T23:08:15.234Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.195110509Z","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-06-15T23:08:15.520Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.481111548Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1"}
5192026-06-15T23:08:15.521Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.481205235Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","migration_id":"2fab055a-3b59-475d-9ccc-5bc3e92133d1","elapsed_milliseconds":3219,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1"}
5202026-06-15T23:08:15.545Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.483166288Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1"}
5212026-06-15T23:08:15.545Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.483465845Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5222026-06-15T23:08:15.545Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.483537661Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5232026-06-15T23:08:15.545Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.485062366Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1"}
5242026-06-15T23:08:15.617Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.577422235Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":94,"vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5252026-06-15T23:08:15.641Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.577703076Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":94,"vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5262026-06-15T23:08:15.641Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.577696193Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":8533,"vm_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","vm":"migration_from_base_and_back_lifecycle_1"}
5272026-06-15T23:08:15.641Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.577816742Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","elapsed_milliseconds":8533,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"2dce15b6-6a29-4872-a932-01669ec72714","source":"migration_from_base_and_back_lifecycle_0"}
5282026-06-15T23:08:15.641Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.577957588Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5292026-06-15T23:08:15.641Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.578057467Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5302026-06-15T23:08:15.666Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.612245087Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":34,"vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5312026-06-15T23:08:15.666Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.612469602Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5322026-06-15T23:08:15.666Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.612781242Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5332026-06-15T23:08:15.666Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.612987823Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":18770}
5342026-06-15T23:08:15.666Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.61318713Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5352026-06-15T23:08:15.666Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.613283642Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5362026-06-15T23:08:15.666Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:15.614308682Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5372026-06-15T23:08:16.178Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.138529052Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5382026-06-15T23:08:16.270Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.22982748Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5392026-06-15T23:08:16.270Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.229952557Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-184f1c45-8d7a-4920-bb04-9141e22eadd7\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5402026-06-15T23:08:16.297Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.257377837Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5412026-06-15T23:08:16.297Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.257476806Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-dd649b55-880e-421b-a28c-6b0fdcc93f20\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5422026-06-15T23:08:16.322Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.277000188Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":664,"vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5432026-06-15T23:08:16.322Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.277215736Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":4613,"vm_id":"c251693a-54bf-4bc4-a11c-abd984688863","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","vm":"migration_from_base_and_back_lifecycle_2"}
5442026-06-15T23:08:16.322Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.277282502Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":664}
5452026-06-15T23:08:16.322Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.277308572Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c251693a-54bf-4bc4-a11c-abd984688863","elapsed_milliseconds":4614,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"7808537b-bca8-48ad-8ce4-d3e3d05ad3fb","source":"migration_from_base_and_back_lifecycle_1"}
5462026-06-15T23:08:16.322Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.277370539Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":20173}
5472026-06-15T23:08:16.322Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.277398332Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5482026-06-15T23:08:16.322Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.277441163Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5492026-06-15T23:08:16.322Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 88.25s
5502026-06-15T23:08:16.322Z
5512026-06-15T23:08:16.322Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":830,"time":"2026-06-15T23:08:16.278150808Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5522026-06-15T23:08:16.451Z
5532026-06-15T23:08:16.451Zreal 1:29.371346738
5542026-06-15T23:08:16.476Zuser 48.621587965
5552026-06-15T23:08:16.476Zsys 21.476617838
5562026-06-15T23:08:16.476Ztrap 0.007094430
5572026-06-15T23:08:16.476Ztflt 0.002342264
5582026-06-15T23:08:16.476Zdflt 0.003646823
5592026-06-15T23:08:16.476Zkflt 0.000004278
5602026-06-15T23:08:16.476Zlock 3:30:54.965999568
5612026-06-15T23:08:16.476Zslp 4:36.827992773
5622026-06-15T23:08:16.476Zlat 1.964908398
5632026-06-15T23:08:16.476Zstop 53.182188187
5642026-06-15T23:08:16.476Z+ failcount=0
5652026-06-15T23:08:16.476Z+ set -e
5662026-06-15T23:08:16.476Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5672026-06-15T23:08:16.501ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5682026-06-15T23:08:16.501Za ./ 0K
5692026-06-15T23:08:16.501Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5702026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 158K
5712026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5722026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5732026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 165K
5742026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5752026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::serial_history/ 0K
5762026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 157K
5772026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5782026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5792026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 164K
5802026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5812026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5822026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 158K
5832026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5842026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5852026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 269K
5862026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5872026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 269K
5882026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5892026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 164K
5902026-06-15T23:08:16.502Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5912026-06-15T23:08:16.502Z+ exitcode=0
5922026-06-15T23:08:16.502Z+ '[' 0 -eq 0 ']'
5932026-06-15T23:08:16.502Z+ echo
5942026-06-15T23:08:16.502Z
5952026-06-15T23:08:16.502Z+ echo 'ALL TESTS PASSED'
5962026-06-15T23:08:16.502ZALL TESTS PASSED
5972026-06-15T23:08:16.502Z+ echo
5982026-06-15T23:08:16.502Z
5992026-06-15T23:08:16.502Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6002026-06-15T23:08:16.502Z+ read
6012026-06-15T23:08:16.502Z+ exit 0
6022026-06-15T23:08:16.502Zprocess exited: duration 134454 ms, exit code 0
 
6032026-06-15T23:08:16.583Zfound 2 output files
6042026-06-15T23:08:16.583Zuploading: /tmp/phd-runner.log (184425 bytes)
6052026-06-15T23:08:17.749Zuploaded: /tmp/phd-runner.log
6062026-06-15T23:08:17.749Zuploading: /tmp/phd-tmp-files.tar.gz (133152 bytes)
6072026-06-15T23:08:18.940Zuploaded: /tmp/phd-tmp-files.tar.gz