01KWMJFTJYHZK3RJ24VP7BMGF1: 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: 01KWMJG5HPSBZVWA3PF1Z48NTK

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-07-03T18:16:04.595Zjob dependencies complete; ready to run (waiting for 10 m 43 s)
22026-07-03T18:24:10.959Zjob assigned to worker 01KWMK3V4HH1603YSN76BS23JY [factory edgar, gimlet/BRM42220010/1208] (queued for 8 m 6 s)
32026-07-03T18:24:11.266Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-07-03T18:24:11.290Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-07-03T18:24:11.290Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-07-03T18:24:11.324Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-07-03T18:24:11.324Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-07-03T18:24:18.681Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-07-03T18:24:18.681Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-07-03T18:24:18.729Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-07-03T18:24:18.753Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-07-03T18:24:28.727Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-07-03T18:24:28.727Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-07-03T18:24:37.052Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-07-03T18:24:37.052Zstarting task 0: "setup"
162026-07-03T18:24:37.076Z++ uname -s
172026-07-03T18:24:37.076Z+ kern=SunOS
182026-07-03T18:24:37.076Z+ build_user=build
192026-07-03T18:24:37.076Z+ build_uid=12345
202026-07-03T18:24:37.077Z+ work_dir=/work
212026-07-03T18:24:37.077Z+ input_dir=/input
222026-07-03T18:24:37.077Z+ [[ 0 == 12345 ]]
232026-07-03T18:24:37.077Z+ case "$kern" in
242026-07-03T18:24:37.077Z+ groupadd -g 12345 build
252026-07-03T18:24:37.102Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-07-03T18:24:39.086Z+ zfs create -o mountpoint=/work rpool/work
272026-07-03T18:24:39.321Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-07-03T18:24:39.345Z+ home_fs=
292026-07-03T18:24:39.345Z+ [[ '' == autofs ]]
302026-07-03T18:24:39.345Z+ mkdir -p /home/build
312026-07-03T18:24:39.345Z+ chown build:build /home/build /work
322026-07-03T18:24:41.333Z+ chmod 0700 /home/build /work
332026-07-03T18:24:41.359Zprocess exited: duration 4286 ms, exit code 0
 
342026-07-03T18:24:41.407Zstarting task 1: "authentication"
352026-07-03T18:24:41.478Zprocess exited: duration 70 ms, exit code 0
 
362026-07-03T18:24:41.527Zstarting task 2: "build"
372026-07-03T18:24:41.554Z+ indir=/input
382026-07-03T18:24:41.554Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-07-03T18:24:41.554Z+ phddir=/work/phd-test
402026-07-03T18:24:41.554Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-07-03T18:24:41.580Z++ pilot local disk list -H -o type,disk
422026-07-03T18:24:41.580Z++ grep -v M.2
432026-07-03T18:24:41.580Z++ cut -f 2
442026-07-03T18:24:41.628Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
452026-07-03T18:24:44.152Z+ artifactdir=/phd-artifacts
462026-07-03T18:24:44.152Z+ banner Inputs
472026-07-03T18:24:44.186Z ###
482026-07-03T18:24:44.186Z # # # ##### # # ##### ####
492026-07-03T18:24:44.186Z # ## # # # # # # #
502026-07-03T18:24:44.186Z # # # # # # # # # ####
512026-07-03T18:24:44.186Z # # # # ##### # # # #
522026-07-03T18:24:44.186Z # # ## # # # # # #
532026-07-03T18:24:44.186Z ### # # # #### # ####
542026-07-03T18:24:44.187Z
552026-07-03T18:24:44.187Z+ find /input -ls
562026-07-03T18:24:44.187Z 34 1 drwxr-xr-x 3 root root 3 Jul 3 18:24 /input
572026-07-03T18:24:44.187Z 2 1 drwxr-xr-x 3 root root 3 Jul 3 18:24 /input/phd-build
582026-07-03T18:24:44.187Z 3 2 drwxr-xr-x 2 root root 8 Jul 3 18:24 /input/phd-build/out
592026-07-03T18:24:44.187Z 384 222148 -rw-r--r-- 1 root root 227551173 Jul 3 18:24 /input/phd-build/out/propolis-server-debug.tar.gz
602026-07-03T18:24:44.187Z 129 1 -rw-r--r-- 1 root root 65 Jul 3 18:24 /input/phd-build/out/phd-runner.sha256.txt
612026-07-03T18:24:44.187Z 256 1 -rw-r--r-- 1 root root 65 Jul 3 18:24 /input/phd-build/out/propolis-server-debug.sha256.txt
622026-07-03T18:24:44.187Z 512 183968 -rw-r--r-- 1 root root 188386556 Jul 3 18:24 /input/phd-build/out/propolis-tests-debug.tar.gz
632026-07-03T18:24:44.187Z 128 2 -rw-r--r-- 1 root root 2573 Jul 3 18:24 /input/phd-build/out/phd-run-with-args.sh
642026-07-03T18:24:44.187Z 130 161992 -rw-r--r-- 1 root root 165808400 Jul 3 18:24 /input/phd-build/out/phd-runner.tar.gz
652026-07-03T18:24:44.187Z+ rm -rf /work/phd-test
662026-07-03T18:24:44.187Z+ mkdir /work/phd-test
672026-07-03T18:24:44.187Z+ for p in $indir/$indir_suffix
682026-07-03T18:24:44.187Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-07-03T18:24:48.573ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-07-03T18:24:48.573Zx phd-runner, 606408216 bytes, 1184392 tape blocks
712026-07-03T18:24:48.573Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-07-03T18:24:48.598Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-07-03T18:24:52.696Z+ for f in $(tar tf "$p")
742026-07-03T18:24:52.697Z+ chmod +x /work/phd-test/phd-runner
752026-07-03T18:24:52.721Z+ for f in $(tar tf "$p")
762026-07-03T18:24:52.721Z+ chmod +x /work/phd-test/artifacts.toml
772026-07-03T18:24:52.721Z+ for p in $indir/$indir_suffix
782026-07-03T18:24:52.721Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-07-03T18:25:14.683ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-07-03T18:25:14.683Zx propolis-server, 871415648 bytes, 1701984 tape blocks
812026-07-03T18:25:14.718Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-07-03T18:25:20.278Z+ for f in $(tar tf "$p")
832026-07-03T18:25:20.278Z+ chmod +x /work/phd-test/propolis-server
842026-07-03T18:25:20.367Z+ for p in $indir/$indir_suffix
852026-07-03T18:25:20.367Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-07-03T18:25:34.271ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-07-03T18:25:34.271Zx target/debug/deps/propolis-a7ca583ea8a8cbd9, 721168920 bytes, 1408534 tape blocks
882026-07-03T18:25:34.296Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-07-03T18:25:38.810Z+ for f in $(tar tf "$p")
902026-07-03T18:25:38.810Z+ chmod +x /work/phd-test/target/debug/deps/propolis-a7ca583ea8a8cbd9
912026-07-03T18:25:38.834Z+ ls /work/phd-test
922026-07-03T18:25:38.834Zartifacts.toml
932026-07-03T18:25:38.834Zphd-runner
942026-07-03T18:25:38.834Zpropolis-server
952026-07-03T18:25:38.834Ztarget
962026-07-03T18:25:38.834Z+ banner Setup
972026-07-03T18:25:38.835Z #####
982026-07-03T18:25:38.835Z# # ###### ##### # # #####
992026-07-03T18:25:38.835Z# # # # # # #
1002026-07-03T18:25:38.835Z ##### ##### # # # # #
1012026-07-03T18:25:38.835Z # # # # # #####
1022026-07-03T18:25:38.835Z# # # # # # #
1032026-07-03T18:25:38.835Z ##### ###### # #### #
1042026-07-03T18:25:38.835Z
1052026-07-03T18:25:38.835Z+ tmpdir=/tmp/propolis-phd
1062026-07-03T18:25:38.835Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-07-03T18:25:38.835Z+ mkdir /tmp/propolis-phd
1082026-07-03T18:25:38.835Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-07-03T18:25:39.355Z+ banner Tests
1102026-07-03T18:25:39.380Z#######
1112026-07-03T18:25:39.380Z # ###### #### ##### ####
1122026-07-03T18:25:39.380Z # # # # #
1132026-07-03T18:25:39.380Z # ##### #### # ####
1142026-07-03T18:25:39.380Z # # # # #
1152026-07-03T18:25:39.380Z # # # # # # #
1162026-07-03T18:25:39.380Z # ###### #### # ####
1172026-07-03T18:25:39.380Z
1182026-07-03T18:25:39.380Z+ runner=/work/phd-test/phd-runner
1192026-07-03T18:25:39.380Z+ artifacts=/work/phd-test/artifacts.toml
1202026-07-03T18:25:39.380Z+ propolis=/work/phd-test/propolis-server
1212026-07-03T18:25:39.380Z+ ls /work/phd-test/phd-runner
1222026-07-03T18:25:39.380Z/work/phd-test/phd-runner
1232026-07-03T18:25:39.380Z+ ls /work/phd-test/artifacts.toml
1242026-07-03T18:25:39.380Z/work/phd-test/artifacts.toml
1252026-07-03T18:25:39.380Z+ ls /work/phd-test/propolis-server
1262026-07-03T18:25:39.380Z/work/phd-test/propolis-server
1272026-07-03T18:25:39.380Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-07-03T18:25:39.380Z+ set +e
1292026-07-03T18:25:39.380Z+ RUST_BACKTRACE=1
1302026-07-03T18:25:39.380Z+ RUST_LOG=info,phd=debug
1312026-07-03T18:25:39.380Z+ 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-07-03T18:25:39.380Z+ tee /tmp/phd-runner.log
1332026-07-03T18:25:39.602Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:39.575851791Z","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-07-03T18:25:39.626Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:39.611980823Z","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: 241, tv_nsec: 714289249 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-07-03T18:25:39.626Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:39.612558948Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-07-03T18:25:39.626Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:39.613692223Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"2bfe090eb5318ec8c467157018db2429d4df535b"}
1372026-07-03T18:25:39.651Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:39.617271008Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/2bfe090eb5318ec8c467157018db2429d4df535b/crucible-nightly.sha256.txt"}
1382026-07-03T18:25:39.872Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:39.859767902Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-07-03T18:25:40.469Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.457500743Z","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/979b72896bc39a876c98fb32fe706da37a4fc408/propolis-server.sha256.txt","timeout":"600s"}
1402026-07-03T18:25:40.635Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.623077288Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-07-03T18:25:40.659Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.624553032Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-07-03T18:25:40.659Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.625431114Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-07-03T18:25:40.659Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.625493552Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-07-03T18:25:40.659Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.625524711Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-07-03T18:25:40.659Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.625556531Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-07-03T18:25:40.659Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.627836267Z","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-07-03T18:25:40.660Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.629928899Z","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-07-03T18:25:40.660Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:40.632253479Z","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-07-03T18:25:41.070Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:41.057899478Z","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-07-03T18:25:41.094Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:41.07132175Z","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-07-03T18:25:47.994Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:47.980179872Z","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-07-03T18:25:48.018Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:47.981613846Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1532026-07-03T18:25:48.018Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:47.999273856Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 3.51M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1542026-07-03T18:25:48.018Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:48.002290817Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-aeefcfbc-c23d-4792-9dba-c72f4a68aad1\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1552026-07-03T18:25:48.042Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:48.026119043Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-aeefcfbc-c23d-4792-9dba-c72f4a68aad1\", \"phd-artifacts/phd-clone-c64c3625-c60f-4db3-ae39-480f56a2357a\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1562026-07-03T18:25:48.067Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:48.043719021Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-c64c3625-c60f-4db3-ae39-480f56a2357a\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1572026-07-03T18:25:48.067Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:48.054955671Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-c64c3625-c60f-4db3-ae39-480f56a2357a 0B 25.3T 49.0M /phd-artifacts/phd-clone-c64c3625-c60f-4db3-ae39-480f56a2357a\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1582026-07-03T18:25:48.091Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:48.05950337Z","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-07-03T18:25:48.091Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:48.059624709Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1602026-07-03T18:25:48.091Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:48.059698169Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/9fe407041bbd80f7b21f15d668ea461fe451f3dec4c2bc2f02e9bf1c85fa3441/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1612026-07-03T18:25:48.091Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:25:48.059765917Z","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/979b72896bc39a876c98fb32fe706da37a4fc408/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1622026-07-03T18:26:00.895Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:00.879834961Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/9fe407041bbd80f7b21f15d668ea461fe451f3dec4c2bc2f02e9bf1c85fa3441/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632026-07-03T18:26:00.895Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:00.879917027Z","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-07-03T18:26:22.239Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.226527925Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/9fe407041bbd80f7b21f15d668ea461fe451f3dec4c2bc2f02e9bf1c85fa3441/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-07-03T18:26:22.239Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.226652571Z","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-07-03T18:26:22.381Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 917","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.368829Z","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-07-03T18:26:22.405Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.383363455Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1682026-07-03T18:26:22.405Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.391477512Z","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":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1692026-07-03T18:26:22.431Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.39579658Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":34335,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1702026-07-03T18:26:22.977Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.964088349Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-07-03T18:26:23.024Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.96652159Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: e24f2ada-73b7-41c3-a1dc-8a49ff64159b, name: \"phd-vm-e24f2ada-73b7-41c3-a1dc-8a49ff64159b\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 7ae69f6e-434f-4c64-8f27-11f68be45196, project_id: 00c0474e-5804-43ce-93f4-2d1db3ca294d, sled_id: 944d4b16-52d6-4f61-b08a-c6de639e6d21, sled_serial: \"944d4b16-52d6-4f61-b08a-c6de639e6d21\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1722026-07-03T18:26:23.024Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.966776322Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1732026-07-03T18:26:23.024Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.966878856Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1742026-07-03T18:26:23.024Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.968512228Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":1,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1752026-07-03T18:26:23.024Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.968643306Z","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-07-03T18:26:23.024Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.9687403Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","timeout_duration":"300s","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1772026-07-03T18:26:23.024Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.96879317Z","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-07-03T18:26:23.024Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.968839778Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1792026-07-03T18:26:23.024Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:22.969479139Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1802026-07-03T18:26:27.553Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.540226895Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":4571,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1812026-07-03T18:26:27.553Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.540316565Z","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-07-03T18:26:27.577Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.541549258Z","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-07-03T18:26:27.577Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.541612658Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1842026-07-03T18:26:27.577Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.541660649Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1852026-07-03T18:26:27.601Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.568226009Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":26,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1862026-07-03T18:26:27.601Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.568376324Z","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-07-03T18:26:27.601Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.568769124Z","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-07-03T18:26:27.601Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.568824768Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1892026-07-03T18:26:27.601Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.568867806Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1902026-07-03T18:26:27.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.601323671Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1912026-07-03T18:26:27.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.601468876Z","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-07-03T18:26:27.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.601548407Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4632,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1932026-07-03T18:26:27.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.601827054Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1942026-07-03T18:26:27.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.602799485Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1952026-07-03T18:26:27.627Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.612563429Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1962026-07-03T18:26:27.627Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.612793484Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1972026-07-03T18:26:27.627Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.6128861Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1982026-07-03T18:26:27.658Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.644943023Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1992026-07-03T18:26:27.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.645185152Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2002026-07-03T18:26:27.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.645280071Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2012026-07-03T18:26:27.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.656065509Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2022026-07-03T18:26:27.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.656305303Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2032026-07-03T18:26:27.683Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.656405132Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2042026-07-03T18:26:27.707Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.689568965Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2052026-07-03T18:26:27.707Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.689822063Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2062026-07-03T18:26:27.707Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.689920415Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2072026-07-03T18:26:27.735Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.700525861Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2082026-07-03T18:26:27.736Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.700755185Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2092026-07-03T18:26:27.736Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.700844434Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2102026-07-03T18:26:27.760Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.734010117Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2112026-07-03T18:26:27.760Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.734322679Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2122026-07-03T18:26:27.760Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.734424862Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2132026-07-03T18:26:27.760Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.745255154Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2142026-07-03T18:26:27.760Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.745563268Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2152026-07-03T18:26:27.760Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.745666463Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2162026-07-03T18:26:27.792Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.778770188Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2172026-07-03T18:26:27.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.779013729Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2182026-07-03T18:26:27.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.779105132Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2192026-07-03T18:26:27.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.790742471Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2202026-07-03T18:26:27.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.79096926Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2212026-07-03T18:26:27.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.791058369Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2222026-07-03T18:26:27.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.814090498Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":23,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2232026-07-03T18:26:27.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.815066886Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2242026-07-03T18:26:27.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.815121901Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2252026-07-03T18:26:27.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.825709744Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2262026-07-03T18:26:27.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.825942875Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2272026-07-03T18:26:27.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.826031934Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2282026-07-03T18:26:27.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.85829613Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2292026-07-03T18:26:27.895Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.859064745Z","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-07-03T18:26:27.895Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.85919947Z","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-07-03T18:26:27.895Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.859264113Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2322026-07-03T18:26:27.895Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.859704586Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","sha256":"None","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2332026-07-03T18:26:27.895Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.859781141Z","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-07-03T18:26:27.895Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.859834532Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2352026-07-03T18:26:27.896Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.859904465Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2362026-07-03T18:26:27.920Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 918","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.903588938Z","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-07-03T18:26:27.945Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.916682605Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":57,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2382026-07-03T18:26:27.945Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.916778176Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2392026-07-03T18:26:27.945Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.916845764Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"0b22a185-be36-4fb7-acbd-388bc3985036","timeout_duration":"45s","target_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2402026-07-03T18:26:27.945Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.916907982Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2412026-07-03T18:26:27.945Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:27.917462602Z","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":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2422026-07-03T18:26:28.767Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:28.754517322Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: bdd80a21-9780-4751-bdfe-67addfbdcedf, name: \"phd-vm-bdd80a21-9780-4751-bdfe-67addfbdcedf\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 7ae69f6e-434f-4c64-8f27-11f68be45196, project_id: 00c0474e-5804-43ce-93f4-2d1db3ca294d, sled_id: 0ccd2a2b-1754-48fc-8a06-d4c593020a62, sled_serial: \"0ccd2a2b-1754-48fc-8a06-d4c593020a62\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2432026-07-03T18:26:28.792Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:28.755333187Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","migration_id":"0b22a185-be36-4fb7-acbd-388bc3985036","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2442026-07-03T18:26:31.711Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:31.698155546Z","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-07-03T18:26:32.506Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:32.493406193Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2462026-07-03T18:26:32.506Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:32.493484231Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","migration_id":"0b22a185-be36-4fb7-acbd-388bc3985036","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":3737}
2472026-07-03T18:26:32.532Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:32.496138195Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2482026-07-03T18:26:32.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:32.497585134Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2492026-07-03T18:26:32.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:32.497649987Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2502026-07-03T18:26:32.532Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:32.500171631Z","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":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2512026-07-03T18:26:32.600Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:32.587575326Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":88,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2522026-07-03T18:26:32.624Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:32.587745498Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":10203,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2532026-07-03T18:26:33.904Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.891446406Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","elapsed_milliseconds":1393,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2542026-07-03T18:26:33.928Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.891750221Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2552026-07-03T18:26:33.928Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.891851072Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2562026-07-03T18:26:33.952Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.925086687Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2572026-07-03T18:26:33.952Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.925349285Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2582026-07-03T18:26:33.952Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.926269667Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2592026-07-03T18:26:33.952Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.926392049Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10961}
2602026-07-03T18:26:33.952Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.926981965Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2612026-07-03T18:26:33.952Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.927088076Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2622026-07-03T18:26:33.953Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:33.92735428Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2632026-07-03T18:26:34.387Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.374425414Z","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":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2642026-07-03T18:26:34.472Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.459832932Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2652026-07-03T18:26:34.473Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.459927Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-c64c3625-c60f-4db3-ae39-480f56a2357a\"]","verb":"destroy","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2662026-07-03T18:26:34.500Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.48787221Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2672026-07-03T18:26:34.500Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.487962961Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-aeefcfbc-c23d-4792-9dba-c72f4a68aad1\"]","verb":"destroy","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2682026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.505351227Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","elapsed_milliseconds":579,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2692026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506053075Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","vm_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","elapsed_milliseconds":6588,"vm":"migration_from_base_lifecycle_0"}
2702026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506122857Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"bdd80a21-9780-4751-bdfe-67addfbdcedf","target":"migration_from_base_lifecycle_0","source":"migration_from_base","source_id":"e24f2ada-73b7-41c3-a1dc-8a49ff64159b","elapsed_milliseconds":6589,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2712026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506169285Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":53875,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506186999Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":579}
2732026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506278221Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2742026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506320081Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2752026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506356299Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2762026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506521272Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2772026-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506611773Z","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-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506677728Z","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-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506737621Z","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-07-03T18:26:34.525Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.506799388Z","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-07-03T18:26:34.550Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.517894502Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.07G 25.3T 1.07G /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2822026-07-03T18:26:34.550Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.517976076Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-de675f08-fad2-4167-854a-056ca12ee464\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::serial_history"}
2832026-07-03T18:26:34.575Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.53781977Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-de675f08-fad2-4167-854a-056ca12ee464\", \"phd-artifacts/phd-clone-294f068a-be66-4c39-aa3a-cb4b7efcb8d7\"]","verb":"clone","path":"phd_tests::migrate::from_base::serial_history"}
2842026-07-03T18:26:34.575Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.554378735Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-294f068a-be66-4c39-aa3a-cb4b7efcb8d7\"]","path":"phd_tests::migrate::from_base::serial_history"}
2852026-07-03T18:26:34.599Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.566531501Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-294f068a-be66-4c39-aa3a-cb4b7efcb8d7 0B 25.3T 1.07G /phd-artifacts/phd-clone-294f068a-be66-4c39-aa3a-cb4b7efcb8d7\n","path":"phd_tests::migrate::from_base::serial_history"}
2862026-07-03T18:26:34.599Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.567151154Z","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-07-03T18:26:34.600Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.567219473Z","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-07-03T18:26:34.600Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.567303983Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/9fe407041bbd80f7b21f15d668ea461fe451f3dec4c2bc2f02e9bf1c85fa3441/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2892026-07-03T18:26:34.600Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.567368786Z","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/9fe407041bbd80f7b21f15d668ea461fe451f3dec4c2bc2f02e9bf1c85fa3441/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
2902026-07-03T18:26:34.600Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.567442014Z","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-07-03T18:26:34.624Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 927","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.607161243Z","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-07-03T18:26:34.648Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.621325375Z","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":54}
2932026-07-03T18:26:34.648Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.621432347Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
2942026-07-03T18:26:34.648Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:34.622149144Z","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::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
2952026-07-03T18:26:35.168Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.155214695Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2962026-07-03T18:26:35.215Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.15591466Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 122ada8a-5f39-4ffc-99d5-d2feb24e41ee, name: \"phd-vm-122ada8a-5f39-4ffc-99d5-d2feb24e41ee\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 2a7b8492-0357-4902-b67a-7fb86706632d, project_id: b36eb17b-89d0-4b16-bfcd-95821d9db3b8, sled_id: 42e7edff-6601-49e0-945c-30ae244a9826, sled_serial: \"42e7edff-6601-49e0-945c-30ae244a9826\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
2972026-07-03T18:26:35.215Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.156059013Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
2982026-07-03T18:26:35.215Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.156108787Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
2992026-07-03T18:26:35.215Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.157058315Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":0}
3002026-07-03T18:26:35.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.15712976Z","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-07-03T18:26:35.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.15718254Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","timeout_duration":"300s","path":"phd_tests::migrate::from_base::serial_history"}
3022026-07-03T18:26:35.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.157225972Z","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-07-03T18:26:35.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.157266589Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3042026-07-03T18:26:35.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:35.157311945Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3052026-07-03T18:26:39.811Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.796555974Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":4639}
3062026-07-03T18:26:39.811Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.796642779Z","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-07-03T18:26:39.839Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.796847717Z","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-07-03T18:26:39.840Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.796904023Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3092026-07-03T18:26:39.840Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.796945872Z","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::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3102026-07-03T18:26:39.840Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.816754932Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":19}
3112026-07-03T18:26:39.840Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.81690685Z","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-07-03T18:26:39.840Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.81718185Z","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-07-03T18:26:39.840Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.817243948Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3142026-07-03T18:26:39.840Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.817291368Z","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::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3152026-07-03T18:26:39.866Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.849207425Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":31}
3162026-07-03T18:26:39.866Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.849358561Z","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-07-03T18:26:39.866Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.849433533Z","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":4692}
3182026-07-03T18:26:39.866Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.849872028Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3192026-07-03T18:26:39.866Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.849967139Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3202026-07-03T18:26:39.890Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.859461224Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":9}
3212026-07-03T18:26:39.890Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.859687292Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3222026-07-03T18:26:39.890Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.85978694Z","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::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3232026-07-03T18:26:39.915Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.893118036Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":33}
3242026-07-03T18:26:39.915Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.893423685Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3252026-07-03T18:26:39.915Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.893524596Z","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::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3262026-07-03T18:26:39.940Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.90416022Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":10}
3272026-07-03T18:26:39.940Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.904397519Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3282026-07-03T18:26:39.940Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.904490786Z","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::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3292026-07-03T18:26:39.965Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.936827469Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":32}
3302026-07-03T18:26:39.965Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.943196865Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_serial_history_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::serial_history"}
3312026-07-03T18:26:39.965Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.943305931Z","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-07-03T18:26:39.965Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.943352339Z","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_serial_history_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
3332026-07-03T18:26:39.965Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.943428473Z","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-07-03T18:26:39.965Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.943480872Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history"}
3352026-07-03T18:26:39.965Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.943549182Z","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-07-03T18:26:39.995Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.982223382Z","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-07-03T18:26:40.021Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.995360151Z","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":52}
3382026-07-03T18:26:40.021Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.995445713Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","target":"migration_serial_history_base_lifecycle_0","target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed"}
3392026-07-03T18:26:40.021Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.995514894Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"3e944dfc-8fd3-42f5-9662-a3c739a822ce","timeout_duration":"45s","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","target":"migration_serial_history_base_lifecycle_0","target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed"}
3402026-07-03T18:26:40.021Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.995575098Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","source":"migration_serial_history_base","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","target":"migration_serial_history_base_lifecycle_0","vm":"migration_serial_history_base_lifecycle_0","target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed"}
3412026-07-03T18:26:40.021Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:39.99610436Z","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)","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","source":"migration_serial_history_base","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","target":"migration_serial_history_base_lifecycle_0","vm":"migration_serial_history_base_lifecycle_0","target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed"}
3422026-07-03T18:26:40.602Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:40.589412569Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: d2aa043f-3118-4d40-9bde-59679b46bbed, name: \"phd-vm-d2aa043f-3118-4d40-9bde-59679b46bbed\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 2a7b8492-0357-4902-b67a-7fb86706632d, project_id: b36eb17b-89d0-4b16-bfcd-95821d9db3b8, sled_id: e306b8bc-1b96-47fe-9d4f-f2fbd8f5360d, sled_serial: \"e306b8bc-1b96-47fe-9d4f-f2fbd8f5360d\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","source":"migration_serial_history_base","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","target":"migration_serial_history_base_lifecycle_0","vm":"migration_serial_history_base_lifecycle_0","target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed"}
3432026-07-03T18:26:40.627Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:40.589626744Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","migration_id":"3e944dfc-8fd3-42f5-9662-a3c739a822ce","source":"migration_serial_history_base","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","target":"migration_serial_history_base_lifecycle_0","target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed"}
3442026-07-03T18:26:43.556Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:43.543625151Z","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-07-03T18:26:44.093Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.080023931Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","target":"migration_serial_history_base_lifecycle_0","target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed"}
3462026-07-03T18:26:44.094Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.08008145Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","migration_id":"3e944dfc-8fd3-42f5-9662-a3c739a822ce","source":"migration_serial_history_base","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":3490,"target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed"}
3472026-07-03T18:26:44.118Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.082376204Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3482026-07-03T18:26:44.118Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.084142107Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base"}
3492026-07-03T18:26:44.183Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.170522364Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":87}
3502026-07-03T18:26:44.207Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.17072103Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base","elapsed_milliseconds":9548}
3512026-07-03T18:26:44.207Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.173593618Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","vm":"migration_serial_history_base_lifecycle_0"}
3522026-07-03T18:26:44.207Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.173761275Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3532026-07-03T18:26:44.207Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.173888145Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9018}
3542026-07-03T18:26:44.207Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.173909837Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3552026-07-03T18:26:44.207Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.174053328Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3562026-07-03T18:26:44.207Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.175403775Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","vm":"migration_serial_history_base_lifecycle_0"}
3572026-07-03T18:26:44.713Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.70035261Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","vm":"migration_serial_history_base_lifecycle_0"}
3582026-07-03T18:26:44.802Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.788918164Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","vm":"migration_serial_history_base_lifecycle_0"}
3592026-07-03T18:26:44.802Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.78904797Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-294f068a-be66-4c39-aa3a-cb4b7efcb8d7\"]","verb":"destroy","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","vm":"migration_serial_history_base_lifecycle_0"}
3602026-07-03T18:26:44.830Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.814326694Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","vm":"migration_serial_history_base_lifecycle_0"}
3612026-07-03T18:26:44.854Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.814387719Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-de675f08-fad2-4167-854a-056ca12ee464\"]","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","vm":"migration_serial_history_base_lifecycle_0"}
3622026-07-03T18:26:44.854Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.831912864Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":658}
3632026-07-03T18:26:44.854Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832116469Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed","path":"phd_tests::migrate::from_base::serial_history","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":4836}
3642026-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832167576Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":658}
3652026-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832211118Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","source_id":"122ada8a-5f39-4ffc-99d5-d2feb24e41ee","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":4836,"target_id":"d2aa043f-3118-4d40-9bde-59679b46bbed"}
3662026-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832271482Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3672026-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832274298Z","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":10325}
3682026-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832315035Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3692026-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832360611Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3702026-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832514502Z","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-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832609893Z","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-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832673574Z","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-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832730211Z","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-07-03T18:26:44.855Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.832796997Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3752026-07-03T18:26:44.879Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.843661905Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.07G 25.3T 1.07G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-07-03T18:26:44.879Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.843751405Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-5d5826f9-9846-4a9d-8d36-0d2bfa79f1f6\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-07-03T18:26:44.879Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.860535035Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-5d5826f9-9846-4a9d-8d36-0d2bfa79f1f6\", \"phd-artifacts/phd-clone-40235b24-4c01-4c2e-9d2f-a676db97a9bb\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-07-03T18:26:44.904Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.877708985Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-40235b24-4c01-4c2e-9d2f-a676db97a9bb\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-07-03T18:26:44.904Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.889001522Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-40235b24-4c01-4c2e-9d2f-a676db97a9bb 0B 25.3T 1.07G /phd-artifacts/phd-clone-40235b24-4c01-4c2e-9d2f-a676db97a9bb\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-07-03T18:26:44.904Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.889577071Z","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-07-03T18:26:44.904Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.889642676Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-07-03T18:26:44.904Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.889711977Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/9fe407041bbd80f7b21f15d668ea461fe451f3dec4c2bc2f02e9bf1c85fa3441/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-07-03T18:26:44.904Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.889776349Z","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/9fe407041bbd80f7b21f15d668ea461fe451f3dec4c2bc2f02e9bf1c85fa3441/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-07-03T18:26:44.904Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.889851541Z","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-07-03T18:26:44.944Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 937","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.931239459Z","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-07-03T18:26:44.968Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.945689291Z","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":56}
3872026-07-03T18:26:44.968Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.945791645Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
3882026-07-03T18:26:44.968Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:44.946487062Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
3892026-07-03T18:26:45.421Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.407300179Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3902026-07-03T18:26:45.445Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.408052413Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a, name: \"phd-vm-ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0193a0a7-3e90-48c9-96b6-dedf665a23eb, project_id: ce9e011c-aa21-41b9-83ba-a3a1c5ef6db3, sled_id: 5296721f-57d0-42ef-a307-e90700b33642, sled_serial: \"5296721f-57d0-42ef-a307-e90700b33642\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
3912026-07-03T18:26:45.445Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.408203038Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
3922026-07-03T18:26:45.445Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.408253815Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
3932026-07-03T18:26:45.445Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.409160541Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":0}
3942026-07-03T18:26:45.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.409241404Z","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-07-03T18:26:45.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.409294956Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","timeout_duration":"300s","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-07-03T18:26:45.446Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.409340321Z","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-07-03T18:26:45.447Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.40938196Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
3982026-07-03T18:26:45.447Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:45.409427446Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
3992026-07-03T18:26:49.990Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.976924048Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4567}
4002026-07-03T18:26:49.990Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.977012115Z","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-07-03T18:26:50.015Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.977203538Z","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-07-03T18:26:50.015Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.977259283Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4032026-07-03T18:26:50.015Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.977298107Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4042026-07-03T18:26:50.015Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.995507546Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":18}
4052026-07-03T18:26:50.015Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.995658682Z","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-07-03T18:26:50.015Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.995909367Z","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-07-03T18:26:50.015Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.995966615Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4082026-07-03T18:26:50.015Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:49.996008775Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4092026-07-03T18:26:50.040Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.027654019Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":31}
4102026-07-03T18:26:50.040Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.027748078Z","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-07-03T18:26:50.041Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.02778618Z","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":4618}
4122026-07-03T18:26:50.065Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.02792894Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4132026-07-03T18:26:50.065Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.028023659Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4142026-07-03T18:26:50.065Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.038794138Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4152026-07-03T18:26:50.065Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.03904322Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4162026-07-03T18:26:50.065Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.039143619Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4172026-07-03T18:26:50.089Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.072534007Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":33}
4182026-07-03T18:26:50.089Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.072845046Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4192026-07-03T18:26:50.089Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.072950005Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4202026-07-03T18:26:50.113Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.08333358Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4212026-07-03T18:26:50.114Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.083549238Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4222026-07-03T18:26:50.114Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.083635126Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4232026-07-03T18:26:50.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.115567288Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":31}
4242026-07-03T18:26:50.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.115899357Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4252026-07-03T18:26:50.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.116004135Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4262026-07-03T18:26:50.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.127248181Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":11}
4272026-07-03T18:26:50.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.127491681Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4282026-07-03T18:26:50.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.127590448Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4292026-07-03T18:26:50.187Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.160362777Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4302026-07-03T18:26:50.187Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.160611738Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4312026-07-03T18:26:50.187Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.160718881Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4322026-07-03T18:26:50.187Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.171512223Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4332026-07-03T18:26:50.187Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.171845033Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4342026-07-03T18:26:50.187Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.171948559Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4352026-07-03T18:26:50.217Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.204301441Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4362026-07-03T18:26:50.241Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.204581592Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4372026-07-03T18:26:50.242Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.204676652Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4382026-07-03T18:26:50.242Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.215326342Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4392026-07-03T18:26:50.242Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.215561748Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4402026-07-03T18:26:50.242Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.215656407Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4412026-07-03T18:26:50.267Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.247852724Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
4422026-07-03T18:26:50.267Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.248111294Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4432026-07-03T18:26:50.267Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.248208358Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4442026-07-03T18:26:50.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.259001931Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
4452026-07-03T18:26:50.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.259242306Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4462026-07-03T18:26:50.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.259338067Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4472026-07-03T18:26:50.315Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.292395324Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":33}
4482026-07-03T18:26:50.315Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.292580254Z","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-07-03T18:26:50.315Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.292718877Z","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-07-03T18:26:50.315Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.292802155Z","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-07-03T18:26:50.315Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.292908676Z","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-07-03T18:26:50.315Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.292994028Z","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::migration_from_base_and_back"}
4532026-07-03T18:26:50.315Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.293112181Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-07-03T18:26:50.343Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.330393744Z","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-07-03T18:26:50.367Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.343430774Z","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":50}
4562026-07-03T18:26:50.367Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.343511226Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4572026-07-03T18:26:50.367Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.343573003Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"caa0d698-cfc9-4c6a-82b5-d4fdfc34a637","target_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4582026-07-03T18:26:50.367Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.343637665Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4592026-07-03T18:26:50.367Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.344221921Z","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":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4602026-07-03T18:26:50.915Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.901605115Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 1907ef1d-d79d-43e0-9ad6-151fbaa655e2, name: \"phd-vm-1907ef1d-d79d-43e0-9ad6-151fbaa655e2\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0193a0a7-3e90-48c9-96b6-dedf665a23eb, project_id: ce9e011c-aa21-41b9-83ba-a3a1c5ef6db3, sled_id: eda7eb97-0ae9-430e-be26-e3ce1b871894, sled_serial: \"eda7eb97-0ae9-430e-be26-e3ce1b871894\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4612026-07-03T18:26:50.915Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:50.901804192Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","target":"migration_from_base_and_back_lifecycle_0","migration_id":"caa0d698-cfc9-4c6a-82b5-d4fdfc34a637","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4622026-07-03T18:26:53.810Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:53.796915405Z","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-07-03T18:26:54.437Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:54.423598754Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4642026-07-03T18:26:54.437Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:54.423656613Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","target":"migration_from_base_and_back_lifecycle_0","migration_id":"caa0d698-cfc9-4c6a-82b5-d4fdfc34a637","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","elapsed_milliseconds":3521,"source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4652026-07-03T18:26:54.461Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:54.426003426Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4662026-07-03T18:26:54.461Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:54.426246797Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4672026-07-03T18:26:54.461Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:54.426309846Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4682026-07-03T18:26:54.461Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:54.427853338Z","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":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4692026-07-03T18:26:54.533Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:54.520023937Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":93}
4702026-07-03T18:26:54.557Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:54.52022112Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":9574}
4712026-07-03T18:26:55.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.518420127Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":1092}
4722026-07-03T18:26:55.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.518612101Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4732026-07-03T18:26:55.532Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.518679338Z","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":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4742026-07-03T18:26:55.565Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.552345338Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":33}
4752026-07-03T18:26:55.565Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.552472539Z","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-07-03T18:26:55.590Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.552601342Z","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-07-03T18:26:55.590Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.552682065Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-07-03T18:26:55.590Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.552791933Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/9fe407041bbd80f7b21f15d668ea461fe451f3dec4c2bc2f02e9bf1c85fa3441/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-07-03T18:26:55.590Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.552893856Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9004","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/9fe407041bbd80f7b21f15d668ea461fe451f3dec4c2bc2f02e9bf1c85fa3441/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-07-03T18:26:55.590Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.553045774Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-07-03T18:26:55.618Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 940","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.594373055Z","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-07-03T18:26:55.643Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.606685293Z","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":54}
4832026-07-03T18:26:55.643Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.606766907Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4842026-07-03T18:26:55.643Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.60683166Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"009b0de0-cc89-4401-a5a5-922f46d3c06a","timeout_duration":"45s","target_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4852026-07-03T18:26:55.646Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.606896913Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4862026-07-03T18:26:55.646Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:55.607428399Z","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":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4872026-07-03T18:26:56.282Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:56.265006352Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd, name: \"phd-vm-88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0193a0a7-3e90-48c9-96b6-dedf665a23eb, project_id: ce9e011c-aa21-41b9-83ba-a3a1c5ef6db3, sled_id: 0f3fddd3-37bc-47f6-9e35-228bb7a2b6eb, sled_serial: \"0f3fddd3-37bc-47f6-9e35-228bb7a2b6eb\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4882026-07-03T18:26:56.282Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:56.265227791Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","target":"migration_from_base_and_back_lifecycle_1","migration_id":"009b0de0-cc89-4401-a5a5-922f46d3c06a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4892026-07-03T18:26:59.260Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:26:59.245898489Z","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-07-03T18:27:00.623Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.609680903Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4912026-07-03T18:27:00.623Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.609761085Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","target":"migration_from_base_and_back_lifecycle_1","migration_id":"009b0de0-cc89-4401-a5a5-922f46d3c06a","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":4344,"source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4922026-07-03T18:27:00.647Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.612115652Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4932026-07-03T18:27:00.647Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.612367419Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
4942026-07-03T18:27:00.647Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.612424327Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
4952026-07-03T18:27:00.647Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.613814418Z","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":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
4962026-07-03T18:27:00.719Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.706237315Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":93}
4972026-07-03T18:27:00.744Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.706470276Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":94}
4982026-07-03T18:27:00.744Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.706515131Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","elapsed_milliseconds":10362,"target_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","vm_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
4992026-07-03T18:27:00.744Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.706666267Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5002026-07-03T18:27:00.744Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.706651699Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","elapsed_milliseconds":10362,"source_id":"ecafd0ab-25c3-4ee1-ae60-2fb11ef0129a"}
5012026-07-03T18:27:00.744Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.706729907Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5022026-07-03T18:27:00.769Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.739899535Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":33}
5032026-07-03T18:27:00.769Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.7400498Z","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-07-03T18:27:00.769Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.740165689Z","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-07-03T18:27:00.769Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.740230151Z","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 }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-07-03T18:27:00.769Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.740315623Z","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-07-03T18:27:00.769Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.740385135Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-07-03T18:27:00.769Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.740477199Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-07-03T18:27:00.795Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 942","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.781831163Z","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-07-03T18:27:00.819Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.794568726Z","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":54}
5112026-07-03T18:27:00.819Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.794665118Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5122026-07-03T18:27:00.819Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.794728909Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"a90e7556-ad75-4364-90cf-7248cecb64bc","target_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5132026-07-03T18:27:00.819Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.794795465Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5142026-07-03T18:27:00.819Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:00.795342019Z","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":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5152026-07-03T18:27:01.575Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:01.562333751Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c283ed4f-7b4a-4b34-b8d8-75d25c337b26, name: \"phd-vm-c283ed4f-7b4a-4b34-b8d8-75d25c337b26\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0193a0a7-3e90-48c9-96b6-dedf665a23eb, project_id: ce9e011c-aa21-41b9-83ba-a3a1c5ef6db3, sled_id: 42069fa1-684d-4cd3-8176-3dcffeecd6aa, sled_serial: \"42069fa1-684d-4cd3-8176-3dcffeecd6aa\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5162026-07-03T18:27:01.576Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:01.562510405Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","target":"migration_from_base_and_back_lifecycle_2","migration_id":"a90e7556-ad75-4364-90cf-7248cecb64bc","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5172026-07-03T18:27:04.481Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.46723078Z","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-07-03T18:27:04.658Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.644740394Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5192026-07-03T18:27:04.658Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.644798605Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","target":"migration_from_base_and_back_lifecycle_2","migration_id":"a90e7556-ad75-4364-90cf-7248cecb64bc","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":3082,"source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5202026-07-03T18:27:04.683Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.647958557Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5212026-07-03T18:27:04.683Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.648365567Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5222026-07-03T18:27:04.684Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.648422926Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5232026-07-03T18:27:04.684Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.649861439Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5242026-07-03T18:27:04.751Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.737688024Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":89}
5252026-07-03T18:27:04.780Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.73802406Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":9130,"target_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","vm_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
5262026-07-03T18:27:04.780Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:04.738159647Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":9131,"source_id":"1907ef1d-d79d-43e0-9ad6-151fbaa655e2"}
5272026-07-03T18:27:08.353Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.340040453Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":3691}
5282026-07-03T18:27:08.377Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.340351161Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5292026-07-03T18:27:08.378Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.340421163Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5302026-07-03T18:27:08.447Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.372531338Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
5312026-07-03T18:27:08.447Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.372697983Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5322026-07-03T18:27:08.447Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.372993843Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5332026-07-03T18:27:08.447Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.373150851Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5342026-07-03T18:27:08.447Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.373231052Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":22965}
5352026-07-03T18:27:08.447Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.373274875Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5362026-07-03T18:27:08.447Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:08.374821012Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5372026-07-03T18:27:09.065Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.051728996Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5382026-07-03T18:27:09.154Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.140900427Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5392026-07-03T18:27:09.154Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.141005876Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-40235b24-4c01-4c2e-9d2f-a676db97a9bb\"]","verb":"destroy","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5402026-07-03T18:27:09.180Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.166900865Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5412026-07-03T18:27:09.203Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.166962582Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-5d5826f9-9846-4a9d-8d36-0d2bfa79f1f6\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26"}
5422026-07-03T18:27:09.203Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.184795571Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":811}
5432026-07-03T18:27:09.203Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.185083145Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":811}
5442026-07-03T18:27:09.203Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.185189657Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5452026-07-03T18:27:09.203Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.185125986Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":8389,"target_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","vm_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5462026-07-03T18:27:09.203Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.185231466Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5472026-07-03T18:27:09.203Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 88.56s
5482026-07-03T18:27:09.203Z
5492026-07-03T18:27:09.203Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.185260671Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"c283ed4f-7b4a-4b34-b8d8-75d25c337b26","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":8390,"source_id":"88e107a5-6b1d-4ed6-b2f9-a30e18ec06fd"}
5502026-07-03T18:27:09.203Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.185339941Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5512026-07-03T18:27:09.204Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-07-03T18:27:09.185342887Z","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":24351}
5522026-07-03T18:27:09.315Z
5532026-07-03T18:27:09.315Zreal 1:29.823527479
5542026-07-03T18:27:09.315Zuser 48.827927944
5552026-07-03T18:27:09.316Zsys 21.435818459
5562026-07-03T18:27:09.340Ztrap 0.007234869
5572026-07-03T18:27:09.340Ztflt 0.002828435
5582026-07-03T18:27:09.340Zdflt 0.002716491
5592026-07-03T18:27:09.340Zkflt 0.000000000
5602026-07-03T18:27:09.340Zlock 3:32:14.594121129
5612026-07-03T18:27:09.340Zslp 4:39.468399599
5622026-07-03T18:27:09.340Zlat 2.055974183
5632026-07-03T18:27:09.340Zstop 45.603441271
5642026-07-03T18:27:09.340Z+ failcount=0
5652026-07-03T18:27:09.340Z+ set -e
5662026-07-03T18:27:09.340Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5672026-07-03T18:27:09.364ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5682026-07-03T18:27:09.365Za ./ 0K
5692026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5702026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 157K
5712026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5722026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5732026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 164K
5742026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5752026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::serial_history/ 0K
5762026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 158K
5772026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5782026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5792026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 165K
5802026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5812026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5822026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 158K
5832026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5842026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5852026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 269K
5862026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5872026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 269K
5882026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5892026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 164K
5902026-07-03T18:27:09.365Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5912026-07-03T18:27:09.365Z+ exitcode=0
5922026-07-03T18:27:09.365Z+ '[' 0 -eq 0 ']'
5932026-07-03T18:27:09.365Z+ echo
5942026-07-03T18:27:09.365Z
5952026-07-03T18:27:09.365Z+ echo 'ALL TESTS PASSED'
5962026-07-03T18:27:09.365ZALL TESTS PASSED
5972026-07-03T18:27:09.365Z+ echo
5982026-07-03T18:27:09.365Z
5992026-07-03T18:27:09.365Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6002026-07-03T18:27:09.365Z+ read
6012026-07-03T18:27:09.366Z+ exit 0
6022026-07-03T18:27:09.366Zprocess exited: duration 147819 ms, exit code 0
 
6032026-07-03T18:27:09.445Zfound 2 output files
6042026-07-03T18:27:09.445Zuploading: /tmp/phd-runner.log (184418 bytes)
6052026-07-03T18:27:10.610Zuploaded: /tmp/phd-runner.log
6062026-07-03T18:27:10.610Zuploading: /tmp/phd-tmp-files.tar.gz (133134 bytes)
6072026-07-03T18:27:11.794Zuploaded: /tmp/phd-tmp-files.tar.gz