01KE81NZXKEY0544943BP0GZDT: 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-opte",
    ),
    access_repos: [],
    publish: [],
    skip_clone: true,
}

Buildomat Job: 01KE81PG8WHVZV4D8X77ZZWVNG

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-01-05T21:53:29.497Zjob dependencies complete; ready to run (waiting for 12 m 25 s)
22026-01-06T01:19:54.730Zjob assigned to worker 01KE8E5CBKG75J8X4S08AHBVK6 [factory lab, buskin/18551] (queued for 3 h 26 m 25 s)
32026-01-06T01:19:54.949Zhttp://172.20.0.5:9969/ipxe/buskin... ok
42026-01-06T01:19:54.995Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/kernel/amd64/unix... ok
52026-01-06T01:19:55.030Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive... ok
62026-01-06T01:19:55.068Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive.hash... ok
72026-01-06T01:19:55.101Zhttp://172.20.0.5:9969/postboot/buskin... ok
82026-01-06T01:19:55.135ZwcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U
92026-01-06T01:19:55.198Zcpu0: microcode has been updated from version 0xa001133 to 0xa0011d5
102026-01-06T01:19:55.236ZOxide Helios Version helios-2.0.23457 64-bit
112026-01-06T01:19:55.269ZConfiguring devices.
122026-01-06T01:19:55.303Z##################################################
132026-01-06T01:19:55.337Z#### ############# ##
142026-01-06T01:19:55.370Z### ### ############ ##
152026-01-06T01:19:55.403Z## ### # ## ### ## Oxide Computer Company ##
162026-01-06T01:19:55.437Z## ## ## ### # ### ##
172026-01-06T01:19:55.470Z## # ### #### #### This Station Under ##
182026-01-06T01:19:55.503Z### ### #### # ### Computer Control ##
192026-01-06T01:19:55.537Z#### #### ### ## ##
202026-01-06T01:19:55.570Z##################################################
212026-01-06T01:19:55.604ZHostname: buskin
222026-01-06T01:19:55.637ZLoading smf(7) service descriptions:
232026-01-06T01:19:56.067Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
242026-01-06T01:19:56.114Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
252026-01-06T01:19:56.114Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
262026-01-06T01:19:56.161Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
272026-01-06T01:19:56.161Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
282026-01-06T01:20:14.216Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
292026-01-06T01:20:14.216Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
302026-01-06T01:20:14.258Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
312026-01-06T01:20:14.258Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
322026-01-06T01:20:43.193Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
332026-01-06T01:20:43.217Zstarting task 0: "setup"
342026-01-06T01:20:43.217Z++ uname -s
352026-01-06T01:20:43.217Z+ kern=SunOS
362026-01-06T01:20:43.217Z+ build_user=build
372026-01-06T01:20:43.217Z+ build_uid=12345
382026-01-06T01:20:43.217Z+ work_dir=/work
392026-01-06T01:20:43.217Z+ input_dir=/input
402026-01-06T01:20:43.217Z+ [[ 0 == 12345 ]]
412026-01-06T01:20:43.217Z+ case "$kern" in
422026-01-06T01:20:43.217Z+ groupadd -g 12345 build
432026-01-06T01:20:43.217Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
442026-01-06T01:20:45.210Z+ zfs create -o mountpoint=/work rpool/work
452026-01-06T01:20:45.234Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
462026-01-06T01:20:45.234Z+ home_fs=zfs
472026-01-06T01:20:45.234Z+ [[ zfs == autofs ]]
482026-01-06T01:20:45.234Z+ mkdir -p /home/build
492026-01-06T01:20:45.234Z+ chown build:build /home/build /work
502026-01-06T01:20:47.235Z+ chmod 0700 /home/build /work
512026-01-06T01:20:47.259Zprocess exited: duration 4045 ms, exit code 0
 
522026-01-06T01:20:47.306Zstarting task 1: "authentication"
532026-01-06T01:20:47.352Zprocess exited: duration 45 ms, exit code 0
 
542026-01-06T01:20:47.401Zstarting task 2: "build"
552026-01-06T01:20:47.425Z+ indir=/input
562026-01-06T01:20:47.425Z+ indir_suffix='phd-build/out/*.tar.gz'
572026-01-06T01:20:47.425Z+ phddir=/work/phd-test
582026-01-06T01:20:47.425Z+ pfexec zpool create -f phd-artifacts c1t1d0 c2t1d0
592026-01-06T01:20:47.579Z+ artifactdir=/phd-artifacts
602026-01-06T01:20:47.579Z+ banner Inputs
612026-01-06T01:20:47.603Z ###
622026-01-06T01:20:47.603Z # # # ##### # # ##### ####
632026-01-06T01:20:47.603Z # ## # # # # # # #
642026-01-06T01:20:47.603Z # # # # # # # # # ####
652026-01-06T01:20:47.603Z # # # # ##### # # # #
662026-01-06T01:20:47.603Z # # ## # # # # # #
672026-01-06T01:20:47.603Z ### # # # #### # ####
682026-01-06T01:20:47.603Z
692026-01-06T01:20:47.603Z+ find /input -ls
702026-01-06T01:20:47.603Z 34 1 drwxr-xr-x 3 root root 3 Jan 6 01:19 /input
712026-01-06T01:20:47.603Z 2 1 drwxr-xr-x 3 root root 3 Jan 6 01:19 /input/phd-build
722026-01-06T01:20:47.604Z 3 2 drwxr-xr-x 2 root root 7 Jan 6 01:20 /input/phd-build/out
732026-01-06T01:20:47.604Z 257 168353 -rw-r--r-- 1 root root 172299524 Jan 6 01:20 /input/phd-build/out/propolis-server-debug.tar.gz
742026-01-06T01:20:47.604Z 128 3 -rw-r--r-- 1 root root 2402 Jan 6 01:19 /input/phd-build/out/phd-run-with-args.sh
752026-01-06T01:20:47.604Z 256 1 -rw-r--r-- 1 root root 65 Jan 6 01:20 /input/phd-build/out/propolis-server-debug.sha256.txt
762026-01-06T01:20:47.604Z 129 1 -rw-r--r-- 1 root root 65 Jan 6 01:19 /input/phd-build/out/phd-runner.sha256.txt
772026-01-06T01:20:47.604Z 130 104177 -rw-r--r-- 1 root root 106609156 Jan 6 01:20 /input/phd-build/out/phd-runner.tar.gz
782026-01-06T01:20:47.604Z+ rm -rf /work/phd-test
792026-01-06T01:20:47.604Z+ mkdir /work/phd-test
802026-01-06T01:20:47.604Z+ for p in $indir/$indir_suffix
812026-01-06T01:20:47.604Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
822026-01-06T01:20:50.178ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
832026-01-06T01:20:50.178Zx phd-runner, 378651616 bytes, 739554 tape blocks
842026-01-06T01:20:50.179Zx artifacts.toml, 548 bytes, 2 tape blocks
852026-01-06T01:20:50.203Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
862026-01-06T01:20:52.347Z+ for f in $(tar tf "$p")
872026-01-06T01:20:52.347Z+ chmod +x /work/phd-test/phd-runner
882026-01-06T01:20:52.372Z+ for f in $(tar tf "$p")
892026-01-06T01:20:52.372Z+ chmod +x /work/phd-test/artifacts.toml
902026-01-06T01:20:52.372Z+ for p in $indir/$indir_suffix
912026-01-06T01:20:52.372Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
922026-01-06T01:20:56.391ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
932026-01-06T01:20:56.391Zx propolis-server, 657594928 bytes, 1284366 tape blocks
942026-01-06T01:20:56.415Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
952026-01-06T01:21:00.005Z+ for f in $(tar tf "$p")
962026-01-06T01:21:00.005Z+ chmod +x /work/phd-test/propolis-server
972026-01-06T01:21:00.029Z+ ls /work/phd-test
982026-01-06T01:21:00.029Zartifacts.toml
992026-01-06T01:21:00.029Zphd-runner
1002026-01-06T01:21:00.029Zpropolis-server
1012026-01-06T01:21:00.029Z+ banner Setup
1022026-01-06T01:21:00.029Z #####
1032026-01-06T01:21:00.029Z# # ###### ##### # # #####
1042026-01-06T01:21:00.029Z# # # # # # #
1052026-01-06T01:21:00.029Z ##### ##### # # # # #
1062026-01-06T01:21:00.029Z # # # # # #####
1072026-01-06T01:21:00.029Z# # # # # # #
1082026-01-06T01:21:00.029Z ##### ###### # #### #
1092026-01-06T01:21:00.029Z
1102026-01-06T01:21:00.029Z+ tmpdir=/tmp/propolis-phd
1112026-01-06T01:21:00.029Z+ '[' '!' -d /tmp/propolis-phd ']'
1122026-01-06T01:21:00.029Z+ mkdir /tmp/propolis-phd
1132026-01-06T01:21:00.029Z+ pfexec /usr/lib/rsrvrctl -s 4096
1142026-01-06T01:21:00.763Z+ banner Tests
1152026-01-06T01:21:00.788Z#######
1162026-01-06T01:21:00.788Z # ###### #### ##### ####
1172026-01-06T01:21:00.788Z # # # # #
1182026-01-06T01:21:00.788Z # ##### #### # ####
1192026-01-06T01:21:00.788Z # # # # #
1202026-01-06T01:21:00.788Z # # # # # # #
1212026-01-06T01:21:00.788Z # ###### #### # ####
1222026-01-06T01:21:00.788Z
1232026-01-06T01:21:00.788Z+ runner=/work/phd-test/phd-runner
1242026-01-06T01:21:00.788Z+ artifacts=/work/phd-test/artifacts.toml
1252026-01-06T01:21:00.788Z+ propolis=/work/phd-test/propolis-server
1262026-01-06T01:21:00.788Z+ ls /work/phd-test/phd-runner
1272026-01-06T01:21:00.788Z/work/phd-test/phd-runner
1282026-01-06T01:21:00.788Z+ ls /work/phd-test/artifacts.toml
1292026-01-06T01:21:00.788Z/work/phd-test/artifacts.toml
1302026-01-06T01:21:00.788Z+ ls /work/phd-test/propolis-server
1312026-01-06T01:21:00.788Z/work/phd-test/propolis-server
1322026-01-06T01:21:00.788Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1332026-01-06T01:21:00.788Z+ set +e
1342026-01-06T01:21:00.788Z+ RUST_BACKTRACE=1
1352026-01-06T01:21:00.788Z+ RUST_LOG=info,phd=debug
1362026-01-06T01:21:00.788Z+ 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
1372026-01-06T01:21:00.788Z+ tee /tmp/phd-runner.log
1382026-01-06T01:21:00.812Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:01.300028813Z","target":"phd_runner","line":36,"file":"phd-tests/runner/src/main.rs","runner_args":"ProcessArgs { command: Run(RunOptions { propolis_server_cmd: \"/work/phd-test/propolis-server\", base_propolis_branch: Some(\"master\"), base_propolis_commit: None, base_propolis_cmd: None, crucible_downstairs_cmd: None, crucible_downstairs_commit: Some(Auto), tmp_directory: \"/tmp/propolis-phd\", artifact_directory: Some(\"/phd-artifacts\"), output_mode: TmpFile, default_guest_cpus: 2, default_guest_memory_mib: 512, artifact_toml_path: \"/work/phd-test/artifacts.toml\", default_guest_artifact: \"alpine\", default_bootrom_artifact: \"ovmf\", include_filter: [\"phd_tests::migrate::from_base\"], exclude_filter: [], max_buildomat_wait_secs: 1200 }), disable_ansi: false, emit_bunyan: true }"}
1392026-01-06T01:21:00.812Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:01.303044996Z","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(\"907a5fd1763ce5ddd74001261e5b52cd200a25f9\"), sha256: \"ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb\" }), 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: 219, tv_nsec: 919810823 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1402026-01-06T01:21:00.813Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:01.303134108Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1412026-01-06T01:21:00.813Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:01.303293723Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"7103cd3a3d7b0112d2949dd135db06fef0c156bb"}
1422026-01-06T01:21:00.813Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:01.303534699Z","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/7103cd3a3d7b0112d2949dd135db06fef0c156bb/crucible-nightly.sha256.txt"}
1432026-01-06T01:21:01.087Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:01.584122815Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1442026-01-06T01:21:01.598Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.094356155Z","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/dacb53d8ec842abd10854ad39d6630033f76bcc2/propolis-server.sha256.txt"}
1452026-01-06T01:21:01.710Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.206585141Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1462026-01-06T01:21:01.736Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.206771046Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1472026-01-06T01:21:01.736Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.206939901Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1482026-01-06T01:21:01.736Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.206978672Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1492026-01-06T01:21:01.736Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.207008313Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1502026-01-06T01:21:01.736Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.207038903Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1512026-01-06T01:21:01.736Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.207504506Z","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"}
1522026-01-06T01:21:01.736Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.208226886Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1532026-01-06T01:21:01.736Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.208555415Z","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/907a5fd1763ce5ddd74001261e5b52cd200a25f9/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1542026-01-06T01:21:02.305Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.801172791Z","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"}
1552026-01-06T01:21:02.329Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:02.801341396Z","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"}
1562026-01-06T01:21:29.581Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.077894605Z","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"}
1572026-01-06T01:21:29.582Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.078006728Z","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"}
1582026-01-06T01:21:29.606Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.085968917Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2.00M 1.80T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1592026-01-06T01:21:29.606Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.086173893Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-f6dde52c-1a61-4399-8801-972c1a8d4930\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1602026-01-06T01:21:29.637Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.133967097Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-f6dde52c-1a61-4399-8801-972c1a8d4930\", \"phd-artifacts/phd-clone-4389f035-e980-4264-a29f-13062262049a\"]","verb":"clone","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1612026-01-06T01:21:29.661Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.14608669Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-4389f035-e980-4264-a29f-13062262049a\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1622026-01-06T01:21:29.662Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.152814015Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-4389f035-e980-4264-a29f-13062262049a 0B 1.80T 48.9M /phd-artifacts/phd-clone-4389f035-e980-4264-a29f-13062262049a\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632026-01-06T01:21:29.662Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.153664909Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1642026-01-06T01:21:29.662Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.153745871Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-01-06T01:21:29.662Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.153804203Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/3ec81e545c55738af3ac5ec7bc94d59a0e3bb7612d9297a9056d35ad6f7f111e/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1662026-01-06T01:21:29.662Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:21:30.153861824Z","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/dacb53d8ec842abd10854ad39d6630033f76bcc2/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1672026-01-06T01:21:59.541Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:00.036988607Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/3ec81e545c55738af3ac5ec7bc94d59a0e3bb7612d9297a9056d35ad6f7f111e/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1682026-01-06T01:21:59.541Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:00.037067999Z","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"}
1692026-01-06T01:22:16.213Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:16.709488485Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/3ec81e545c55738af3ac5ec7bc94d59a0e3bb7612d9297a9056d35ad6f7f111e/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1702026-01-06T01:22:16.213Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:16.709618548Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/migration_from_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1712026-01-06T01:22:16.277Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 868","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:16.773811503Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1722026-01-06T01:22:16.302Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:16.774238045Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1732026-01-06T01:22:16.302Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:16.775100889Z","target":"phd_framework::test_vm","line":347,"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":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1742026-01-06T01:22:16.302Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:16.775399717Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":46621}
1752026-01-06T01:22:16.569Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.066189993Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1762026-01-06T01:22:16.594Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.067071057Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: ffecedae-ba04-40c4-9a31-8affdabb2f46, name: \"phd-vm-ffecedae-ba04-40c4-9a31-8affdabb2f46\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: b3cb2832-6bea-4cae-a0e9-d30bd7e851b2, project_id: aef2e91c-430e-47c4-b27b-573719111880, sled_id: 950945ac-57c9-4483-a0bf-fcaed3d4ea90, sled_serial: \"950945ac-57c9-4483-a0bf-fcaed3d4ea90\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1772026-01-06T01:22:16.594Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.06719246Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1782026-01-06T01:22:16.594Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.067237501Z","target":"phd_framework::test_vm","line":472,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1792026-01-06T01:22:16.594Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.06791952Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":0,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
1802026-01-06T01:22:16.594Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.068010573Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1812026-01-06T01:22:16.594Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.068058914Z","target":"phd_framework::test_vm","line":731,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_from_base","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1822026-01-06T01:22:16.594Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.068096605Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1832026-01-06T01:22:16.594Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.068161517Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1842026-01-06T01:22:16.594Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:17.068212438Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1852026-01-06T01:22:21.086Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.582454927Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":4514,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
1862026-01-06T01:22:21.086Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.58253818Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1872026-01-06T01:22:21.110Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.582865319Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1882026-01-06T01:22:21.110Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.58291736Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1892026-01-06T01:22:21.110Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.582958741Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1902026-01-06T01:22:21.110Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.601232464Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":18,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
1912026-01-06T01:22:21.110Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.601365267Z","target":"phd_framework::test_vm","line":739,"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"}
1922026-01-06T01:22:21.110Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.601741368Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1932026-01-06T01:22:21.110Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.60182722Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1942026-01-06T01:22:21.110Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.601872872Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1952026-01-06T01:22:21.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.634636453Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
1962026-01-06T01:22:21.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.634747796Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1972026-01-06T01:22:21.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.634836238Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4566}
1982026-01-06T01:22:21.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.635083205Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1992026-01-06T01:22:21.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.635170277Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2002026-01-06T01:22:21.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.645617264Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":10,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2012026-01-06T01:22:21.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.64582265Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2022026-01-06T01:22:21.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.645907272Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2032026-01-06T01:22:21.186Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.67889931Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2042026-01-06T01:22:21.187Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.679176817Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2052026-01-06T01:22:21.187Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.67926517Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2062026-01-06T01:22:21.211Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.689673376Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":10,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2072026-01-06T01:22:21.211Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.68981449Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2082026-01-06T01:22:21.211Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.689872951Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2092026-01-06T01:22:21.235Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.722741595Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2102026-01-06T01:22:21.235Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.722957641Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2112026-01-06T01:22:21.235Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.723050184Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2122026-01-06T01:22:21.259Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.733534252Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":10,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2132026-01-06T01:22:21.259Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.733757048Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2142026-01-06T01:22:21.259Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.73384006Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2152026-01-06T01:22:21.283Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.756342699Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":22,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2162026-01-06T01:22:21.283Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.756443622Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2172026-01-06T01:22:21.283Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.756522184Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2182026-01-06T01:22:21.283Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.756571125Z","target":"phd_framework::test_vm","line":217,"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"}
2192026-01-06T01:22:21.284Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.756643237Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","sha256":"None","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2202026-01-06T01:22:21.284Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.756699159Z","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"}
2212026-01-06T01:22:21.284Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.75675144Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2222026-01-06T01:22:21.284Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.756803112Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2232026-01-06T01:22:21.308Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 869","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.781932433Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2242026-01-06T01:22:21.308Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.78218406Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":25}
2252026-01-06T01:22:21.308Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.782274182Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2262026-01-06T01:22:21.308Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.782376475Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"5943c83a-9ba1-4b4f-a8d0-c4f2aa4348e2","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2272026-01-06T01:22:21.308Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.782450837Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","vm":"migration_from_base_lifecycle_0","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2282026-01-06T01:22:21.308Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:21.782960921Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","vm":"migration_from_base_lifecycle_0","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2292026-01-06T01:22:21.827Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:22.323679339Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a, name: \"phd-vm-e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: b3cb2832-6bea-4cae-a0e9-d30bd7e851b2, project_id: aef2e91c-430e-47c4-b27b-573719111880, sled_id: f658d600-cc0f-4693-bc18-5c6f4b2aa817, sled_serial: \"f658d600-cc0f-4693-bc18-5c6f4b2aa817\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","vm":"migration_from_base_lifecycle_0","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2302026-01-06T01:22:21.851Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:22.323831363Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","migration_id":"5943c83a-9ba1-4b4f-a8d0-c4f2aa4348e2","target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2312026-01-06T01:22:24.078Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:24.574654534Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7760}}"}
2322026-01-06T01:22:25.425Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:25.921211132Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2332026-01-06T01:22:25.425Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:25.921265013Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","migration_id":"5943c83a-9ba1-4b4f-a8d0-c4f2aa4348e2","elapsed_milliseconds":3597,"target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2342026-01-06T01:22:25.449Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:25.923381321Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2352026-01-06T01:22:25.449Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:25.9237127Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2362026-01-06T01:22:25.449Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:25.923768352Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2372026-01-06T01:22:25.449Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:25.924869202Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2382026-01-06T01:22:25.507Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.00300826Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":79,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2392026-01-06T01:22:25.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.003137583Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":79,"vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a"}
2402026-01-06T01:22:25.507Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.003172464Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":9228,"vm_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2412026-01-06T01:22:25.531Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.003334379Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2422026-01-06T01:22:25.531Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.003397501Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2432026-01-06T01:22:25.555Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.034058474Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":30,"vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a"}
2442026-01-06T01:22:25.555Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.034185957Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2452026-01-06T01:22:25.555Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.034339661Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2462026-01-06T01:22:25.555Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.034398573Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
2472026-01-06T01:22:25.555Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.034436244Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8968}
2482026-01-06T01:22:25.555Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.034452765Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2492026-01-06T01:22:25.555Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.035339559Z","target":"phd_framework::test_vm","line":1077,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2502026-01-06T01:22:25.882Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.378211967Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2512026-01-06T01:22:25.961Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.456942962Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2522026-01-06T01:22:25.961Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.457035215Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-4389f035-e980-4264-a29f-13062262049a\"]","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2532026-01-06T01:22:25.985Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.475937404Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2542026-01-06T01:22:25.985Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.475983446Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-f6dde52c-1a61-4399-8801-972c1a8d4930\"]","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2552026-01-06T01:22:26.009Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489296832Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":454,"vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a"}
2562026-01-06T01:22:26.009Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489481407Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":454}
2572026-01-06T01:22:26.009Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489491707Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","vm_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","source":"migration_from_base","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":4706,"target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2582026-01-06T01:22:26.009Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489527658Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
2592026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489554179Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2602026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489549579Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"e2ff7d8d-f8be-4f39-8635-7de1fd7ffc4a","elapsed_milliseconds":4707,"target":"migration_from_base_lifecycle_0","source_id":"ffecedae-ba04-40c4-9a31-8affdabb2f46"}
2612026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.48958215Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2622026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.48959454Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":84281}
2632026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489678073Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2642026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489779415Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
2652026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489837487Z","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"}
2662026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.489894768Z","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"}
2672026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.4899552Z","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"}
2682026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.496936072Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 860M 1.80T 860M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2692026-01-06T01:22:26.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.497010884Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-22ee1e6e-76df-4ec1-9ea4-2b66874de54c\"]","path":"phd_tests::migrate::from_base::serial_history"}
2702026-01-06T01:22:26.060Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.510391442Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-22ee1e6e-76df-4ec1-9ea4-2b66874de54c\", \"phd-artifacts/phd-clone-b0d9f7f9-35a5-42e0-9137-41836db8f381\"]","path":"phd_tests::migrate::from_base::serial_history"}
2712026-01-06T01:22:26.083Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.523236565Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-b0d9f7f9-35a5-42e0-9137-41836db8f381\"]","path":"phd_tests::migrate::from_base::serial_history"}
2722026-01-06T01:22:26.083Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.529661112Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-b0d9f7f9-35a5-42e0-9137-41836db8f381 0B 1.80T 860M /phd-artifacts/phd-clone-b0d9f7f9-35a5-42e0-9137-41836db8f381\n","path":"phd_tests::migrate::from_base::serial_history"}
2732026-01-06T01:22:26.084Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.530117024Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2742026-01-06T01:22:26.084Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.530165616Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
2752026-01-06T01:22:26.084Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.530214497Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/3ec81e545c55738af3ac5ec7bc94d59a0e3bb7612d9297a9056d35ad6f7f111e/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2762026-01-06T01:22:26.084Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.530259748Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/3ec81e545c55738af3ac5ec7bc94d59a0e3bb7612d9297a9056d35ad6f7f111e/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
2772026-01-06T01:22:26.084Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.53030349Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/migration_serial_history_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_serial_history_base.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2782026-01-06T01:22:26.084Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 878","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.553925629Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
2792026-01-06T01:22:26.084Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.554139085Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":23,"path":"phd_tests::migrate::from_base::serial_history"}
2802026-01-06T01:22:26.084Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.554225707Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2812026-01-06T01:22:26.084Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:26.554786033Z","target":"phd_framework::test_vm","line":347,"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":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2822026-01-06T01:22:26.763Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.259599483Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2832026-01-06T01:22:26.789Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.260568699Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c9f37be5-f73a-4e94-8929-141e4039bdc4, name: \"phd-vm-c9f37be5-f73a-4e94-8929-141e4039bdc4\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: a019f9b5-934d-4866-93ef-fb6cd018b4bf, project_id: dfd472af-29d0-40d3-8e8a-baba5a9a7c98, sled_id: 8138d98c-e444-4021-88d0-bd063d72ec8c, sled_serial: \"8138d98c-e444-4021-88d0-bd063d72ec8c\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2842026-01-06T01:22:26.789Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.260692053Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2852026-01-06T01:22:26.789Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.260734464Z","target":"phd_framework::test_vm","line":472,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2862026-01-06T01:22:26.789Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.261399313Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2872026-01-06T01:22:26.789Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.261460664Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2882026-01-06T01:22:26.789Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.261504285Z","target":"phd_framework::test_vm","line":731,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","timeout_duration":"300s","path":"phd_tests::migrate::from_base::serial_history"}
2892026-01-06T01:22:26.789Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.261540996Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
2902026-01-06T01:22:26.789Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.261574567Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2912026-01-06T01:22:26.789Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:27.261611328Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2922026-01-06T01:22:31.186Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.682288936Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4420,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2932026-01-06T01:22:31.186Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.682372938Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
2942026-01-06T01:22:31.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.682544883Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
2952026-01-06T01:22:31.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.682596664Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2962026-01-06T01:22:31.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.682636405Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2972026-01-06T01:22:31.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.701277938Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
2982026-01-06T01:22:31.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.70134812Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
2992026-01-06T01:22:31.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.701541365Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3002026-01-06T01:22:31.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.701605197Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3012026-01-06T01:22:31.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.701648928Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3022026-01-06T01:22:31.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.734315376Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3032026-01-06T01:22:31.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.734377888Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3042026-01-06T01:22:31.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.734421939Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4472,"path":"phd_tests::migrate::from_base::serial_history"}
3052026-01-06T01:22:31.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.734550463Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3062026-01-06T01:22:31.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.734608314Z","target":"phd_framework::test_vm","line":804,"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":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3072026-01-06T01:22:31.262Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.746000598Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3082026-01-06T01:22:31.262Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.746210514Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3092026-01-06T01:22:31.262Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.746294676Z","target":"phd_framework::test_vm","line":804,"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":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3102026-01-06T01:22:31.286Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.778902672Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3112026-01-06T01:22:31.310Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.783598622Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3122026-01-06T01:22:31.310Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.783703664Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3132026-01-06T01:22:31.310Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.783748396Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3142026-01-06T01:22:31.310Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.783805797Z","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"}
3152026-01-06T01:22:31.310Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.783854618Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history"}
3162026-01-06T01:22:31.310Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.78389702Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
3172026-01-06T01:22:31.334Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 879","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.807735725Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
3182026-01-06T01:22:31.334Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.808023533Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":24,"path":"phd_tests::migrate::from_base::serial_history"}
3192026-01-06T01:22:31.335Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.808132596Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base"}
3202026-01-06T01:22:31.335Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.808222099Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"a75d3a1d-a4c9-4eb9-9737-9e31d1b5501f","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base"}
3212026-01-06T01:22:31.335Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.808312801Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base","vm":"migration_serial_history_base_lifecycle_0"}
3222026-01-06T01:22:31.335Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:31.808970659Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base","vm":"migration_serial_history_base_lifecycle_0"}
3232026-01-06T01:22:31.650Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:32.147123057Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 37818d5c-871c-42e5-bd8a-88bc0a0f6ea7, name: \"phd-vm-37818d5c-871c-42e5-bd8a-88bc0a0f6ea7\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: a019f9b5-934d-4866-93ef-fb6cd018b4bf, project_id: dfd472af-29d0-40d3-8e8a-baba5a9a7c98, sled_id: 7ac1060d-86d5-4d95-a01a-e6108142ffcc, sled_serial: \"7ac1060d-86d5-4d95-a01a-e6108142ffcc\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base","vm":"migration_serial_history_base_lifecycle_0"}
3242026-01-06T01:22:31.674Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:32.147274991Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base","migration_id":"a75d3a1d-a4c9-4eb9-9737-9e31d1b5501f"}
3252026-01-06T01:22:33.931Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:34.427986895Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7727}}"}
3262026-01-06T01:22:34.689Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.185420782Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base"}
3272026-01-06T01:22:34.689Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.185478664Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3038,"path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base","migration_id":"a75d3a1d-a4c9-4eb9-9737-9e31d1b5501f"}
3282026-01-06T01:22:34.713Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.187118329Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3292026-01-06T01:22:34.713Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.188411914Z","target":"phd_framework::test_vm::server","line":140,"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":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3302026-01-06T01:22:34.767Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.263927281Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":76,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3312026-01-06T01:22:34.791Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.264116786Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":8709,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","vm":"migration_serial_history_base"}
3322026-01-06T01:22:34.791Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.266595484Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","vm":"migration_serial_history_base_lifecycle_0"}
3332026-01-06T01:22:34.791Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.266743218Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3342026-01-06T01:22:34.791Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.266850361Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8007}
3352026-01-06T01:22:34.791Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.266851041Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3362026-01-06T01:22:34.791Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.266924453Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3372026-01-06T01:22:34.791Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.267740366Z","target":"phd_framework::test_vm","line":1077,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","vm":"migration_serial_history_base_lifecycle_0"}
3382026-01-06T01:22:35.056Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.552159527Z","target":"phd_framework::test_vm::server","line":140,"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":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","vm":"migration_serial_history_base_lifecycle_0"}
3392026-01-06T01:22:35.134Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.630162382Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","vm":"migration_serial_history_base_lifecycle_0"}
3402026-01-06T01:22:35.134Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.630220473Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-b0d9f7f9-35a5-42e0-9137-41836db8f381\"]","path":"phd_tests::migrate::from_base::serial_history","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","vm":"migration_serial_history_base_lifecycle_0"}
3412026-01-06T01:22:35.159Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.649342619Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","vm":"migration_serial_history_base_lifecycle_0"}
3422026-01-06T01:22:35.159Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.64939791Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-22ee1e6e-76df-4ec1-9ea4-2b66874de54c\"]","path":"phd_tests::migrate::from_base::serial_history","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","vm":"migration_serial_history_base_lifecycle_0"}
3432026-01-06T01:22:35.183Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661104532Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":394,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","vm":"migration_serial_history_base_lifecycle_0"}
3442026-01-06T01:22:35.183Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661207405Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":3852,"source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","vm_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base"}
3452026-01-06T01:22:35.183Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661219766Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":394}
3462026-01-06T01:22:35.183Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661253487Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3853,"path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c9f37be5-f73a-4e94-8929-141e4039bdc4","target_id":"37818d5c-871c-42e5-bd8a-88bc0a0f6ea7","source":"migration_serial_history_base"}
3472026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661269117Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3482026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661286817Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":9171,"path":"phd_tests::migrate::from_base::serial_history"}
3492026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661296648Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3502026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661325349Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3512026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661425581Z","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"}
3522026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661498763Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3532026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661546025Z","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"}
3542026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661594516Z","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"}
3552026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.661645177Z","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"}
3562026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.668774883Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 861M 1.80T 860M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3572026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.668853016Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-6bd6382f-6d91-455f-ae8b-512b61bf1dad\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3582026-01-06T01:22:35.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.678776228Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-6bd6382f-6d91-455f-ae8b-512b61bf1dad\", \"phd-artifacts/phd-clone-936fd65e-0c72-4eca-8588-77b5b8be65cf\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3592026-01-06T01:22:35.209Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.693609996Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-936fd65e-0c72-4eca-8588-77b5b8be65cf\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3602026-01-06T01:22:35.209Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.700809054Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-936fd65e-0c72-4eca-8588-77b5b8be65cf 0B 1.80T 860M /phd-artifacts/phd-clone-936fd65e-0c72-4eca-8588-77b5b8be65cf\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3612026-01-06T01:22:35.209Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.701239776Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3622026-01-06T01:22:35.209Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.701291217Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3632026-01-06T01:22:35.209Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.701336549Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/3ec81e545c55738af3ac5ec7bc94d59a0e3bb7612d9297a9056d35ad6f7f111e/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3642026-01-06T01:22:35.210Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.70138236Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/3ec81e545c55738af3ac5ec7bc94d59a0e3bb7612d9297a9056d35ad6f7f111e/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3652026-01-06T01:22:35.210Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.701427871Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3662026-01-06T01:22:35.234Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 888","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.725651127Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3672026-01-06T01:22:35.234Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.725867373Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":24}
3682026-01-06T01:22:35.234Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.725951736Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3692026-01-06T01:22:35.234Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:35.726419559Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3702026-01-06T01:22:35.688Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.184823553Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3712026-01-06T01:22:35.712Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.185356938Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: f48378a5-f937-4ca1-aa18-dea5a0912aec, name: \"phd-vm-f48378a5-f937-4ca1-aa18-dea5a0912aec\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f36e587b-fc87-4ac7-a557-70b946ac96ac, project_id: 55efea12-09c0-4580-9c2b-188e80db1589, sled_id: 5ab710cb-b94a-42fb-a503-786bee2d3eb0, sled_serial: \"5ab710cb-b94a-42fb-a503-786bee2d3eb0\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3722026-01-06T01:22:35.712Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.185452231Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3732026-01-06T01:22:35.712Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.185502132Z","target":"phd_framework::test_vm","line":472,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3742026-01-06T01:22:35.712Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.186555811Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":1}
3752026-01-06T01:22:35.712Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.186632123Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-01-06T01:22:35.712Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.186689305Z","target":"phd_framework::test_vm","line":731,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","vm":"migration_from_base_and_back","timeout_duration":"300s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-01-06T01:22:35.712Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.186736216Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-01-06T01:22:35.712Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.186780997Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3792026-01-06T01:22:35.713Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:36.186845969Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3802026-01-06T01:22:40.170Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.666006094Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":4479}
3812026-01-06T01:22:40.170Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.666086336Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-01-06T01:22:40.194Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.666257891Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-01-06T01:22:40.194Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.666309162Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3842026-01-06T01:22:40.194Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.666350623Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3852026-01-06T01:22:40.194Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.683427773Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":17}
3862026-01-06T01:22:40.194Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.683499325Z","target":"phd_framework::test_vm","line":739,"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"}
3872026-01-06T01:22:40.194Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.68368288Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3882026-01-06T01:22:40.194Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.683745972Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3892026-01-06T01:22:40.194Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.683792983Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3902026-01-06T01:22:40.220Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.716641766Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":32}
3912026-01-06T01:22:40.220Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.716735659Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3922026-01-06T01:22:40.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.716797201Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4530}
3932026-01-06T01:22:40.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.716991956Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3942026-01-06T01:22:40.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.717077669Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3952026-01-06T01:22:40.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.727492185Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":10}
3962026-01-06T01:22:40.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.727706651Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3972026-01-06T01:22:40.244Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.727791603Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
3982026-01-06T01:22:40.268Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.760951635Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":33}
3992026-01-06T01:22:40.268Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.761175791Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4002026-01-06T01:22:40.268Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.761277274Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4012026-01-06T01:22:40.292Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.771803163Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":10}
4022026-01-06T01:22:40.293Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.772014779Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4032026-01-06T01:22:40.293Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.772100402Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4042026-01-06T01:22:40.317Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.805001176Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":32}
4052026-01-06T01:22:40.317Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.80514273Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4062026-01-06T01:22:40.317Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.805200822Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4072026-01-06T01:22:40.341Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.815484004Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":10}
4082026-01-06T01:22:40.341Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.81567048Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4092026-01-06T01:22:40.341Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.815727341Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4102026-01-06T01:22:40.365Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.838313432Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":22}
4112026-01-06T01:22:40.365Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.838430825Z","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"}
4122026-01-06T01:22:40.365Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.838506008Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4132026-01-06T01:22:40.365Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.838555709Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4142026-01-06T01:22:40.365Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.838621421Z","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"}
4152026-01-06T01:22:40.365Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.838675682Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4162026-01-06T01:22:40.365Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.838728303Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4172026-01-06T01:22:40.390Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 889","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.863398922Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-01-06T01:22:40.390Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.86368064Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":25}
4192026-01-06T01:22:40.390Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.863783883Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","target_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4202026-01-06T01:22:40.390Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.863872915Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"3a9f17c3-bb22-4dcf-a568-a6e90a83d059","timeout_duration":"45s","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","target_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4212026-01-06T01:22:40.390Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.863957967Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2","target_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4222026-01-06T01:22:40.390Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:40.864519573Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2","target_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4232026-01-06T01:22:40.651Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:41.147583086Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 1655f74f-299d-4397-9101-6100a1bab6f2, name: \"phd-vm-1655f74f-299d-4397-9101-6100a1bab6f2\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f36e587b-fc87-4ac7-a557-70b946ac96ac, project_id: 55efea12-09c0-4580-9c2b-188e80db1589, sled_id: 4672b32b-2ce1-4b6a-8998-7878ae180449, sled_serial: \"4672b32b-2ce1-4b6a-8998-7878ae180449\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2","target_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4242026-01-06T01:22:40.651Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:41.147703629Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","migration_id":"3a9f17c3-bb22-4dcf-a568-a6e90a83d059","target_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4252026-01-06T01:22:42.939Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.435570349Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7760}}"}
4262026-01-06T01:22:43.213Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.709752408Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","target_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4272026-01-06T01:22:43.213Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.70981036Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","migration_id":"3a9f17c3-bb22-4dcf-a568-a6e90a83d059","elapsed_milliseconds":2562,"target_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4282026-01-06T01:22:43.238Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.711410854Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4292026-01-06T01:22:43.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.711586319Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4302026-01-06T01:22:43.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.71164408Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4312026-01-06T01:22:43.238Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.712498204Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec"}
4322026-01-06T01:22:43.292Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.789161832Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":77}
4332026-01-06T01:22:43.317Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.789361497Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","elapsed_milliseconds":8063}
4342026-01-06T01:22:43.317Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.789412119Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2","elapsed_milliseconds":77}
4352026-01-06T01:22:43.317Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.789568353Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4362026-01-06T01:22:43.317Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.789634135Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4372026-01-06T01:22:43.341Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.822319234Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2","elapsed_milliseconds":32}
4382026-01-06T01:22:43.341Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.822384905Z","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"}
4392026-01-06T01:22:43.341Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.822441027Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4402026-01-06T01:22:43.341Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.822482138Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_1","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4412026-01-06T01:22:43.341Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.822538Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/3ec81e545c55738af3ac5ec7bc94d59a0e3bb7612d9297a9056d35ad6f7f111e/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4422026-01-06T01:22:43.341Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.822585481Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9004","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/3ec81e545c55738af3ac5ec7bc94d59a0e3bb7612d9297a9056d35ad6f7f111e/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4432026-01-06T01:22:43.341Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.822630542Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4442026-01-06T01:22:43.366Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 891","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.847458885Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4452026-01-06T01:22:43.366Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.847715402Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":25}
4462026-01-06T01:22:43.366Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.847822035Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4472026-01-06T01:22:43.366Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.847918318Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"afa78a2b-9299-44f9-8169-90219cfc0a53","timeout_duration":"45s","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4482026-01-06T01:22:43.366Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.84801479Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4492026-01-06T01:22:43.366Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:43.848512604Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4502026-01-06T01:22:44.039Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:44.535645918Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 6780680d-bcc8-4e2c-81bc-3e128258bc3c, name: \"phd-vm-6780680d-bcc8-4e2c-81bc-3e128258bc3c\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f36e587b-fc87-4ac7-a557-70b946ac96ac, project_id: 55efea12-09c0-4580-9c2b-188e80db1589, sled_id: 4779d5e4-133e-4a17-acda-3fe6adc135c9, sled_serial: \"4779d5e4-133e-4a17-acda-3fe6adc135c9\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4512026-01-06T01:22:44.039Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:44.535770692Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","migration_id":"afa78a2b-9299-44f9-8169-90219cfc0a53","target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4522026-01-06T01:22:46.339Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:46.834946394Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7807}}"}
4532026-01-06T01:22:47.860Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.35461215Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4542026-01-06T01:22:47.860Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.354667401Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","migration_id":"afa78a2b-9299-44f9-8169-90219cfc0a53","elapsed_milliseconds":3818,"target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4552026-01-06T01:22:47.885Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.356421989Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4562026-01-06T01:22:47.885Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.356594824Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4572026-01-06T01:22:47.885Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.356648185Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4582026-01-06T01:22:47.885Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.357511129Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4592026-01-06T01:22:47.938Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.434773494Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2","elapsed_milliseconds":78}
4602026-01-06T01:22:47.962Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.43498208Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","elapsed_milliseconds":78}
4612026-01-06T01:22:47.962Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.435053481Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","elapsed_milliseconds":7570,"target_id":"1655f74f-299d-4397-9101-6100a1bab6f2","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4622026-01-06T01:22:47.962Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.435139424Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f48378a5-f937-4ca1-aa18-dea5a0912aec","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":7571,"target_id":"1655f74f-299d-4397-9101-6100a1bab6f2"}
4632026-01-06T01:22:47.962Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.435163384Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4642026-01-06T01:22:47.962Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.435232886Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4652026-01-06T01:22:47.987Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.467118063Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","elapsed_milliseconds":31}
4662026-01-06T01:22:47.987Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.467196596Z","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"}
4672026-01-06T01:22:47.987Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.467262567Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4682026-01-06T01:22:47.987Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.467310139Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4692026-01-06T01:22:47.987Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.46737261Z","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"}
4702026-01-06T01:22:47.987Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.467423312Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4712026-01-06T01:22:47.987Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.467473143Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4722026-01-06T01:22:48.011Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 893","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.491649668Z","target":"phd_framework::test_vm::server","line":122,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4732026-01-06T01:22:48.012Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.491854554Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":24}
4742026-01-06T01:22:48.012Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.491945776Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4752026-01-06T01:22:48.012Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.492014958Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"93b51eee-a73a-4b20-a710-65377df3f566","timeout_duration":"45s","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4762026-01-06T01:22:48.012Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.49208659Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e","target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4772026-01-06T01:22:48.012Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.492537092Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e","target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4782026-01-06T01:22:48.463Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.959686958Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 9a781ff1-f391-4d5e-a384-d4f1ae1b064e, name: \"phd-vm-9a781ff1-f391-4d5e-a384-d4f1ae1b064e\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: f36e587b-fc87-4ac7-a557-70b946ac96ac, project_id: 55efea12-09c0-4580-9c2b-188e80db1589, sled_id: bb38d2ee-0b38-478e-9eee-c14eb17c947e, sled_serial: \"bb38d2ee-0b38-478e-9eee-c14eb17c947e\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e","target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4792026-01-06T01:22:48.463Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:48.959828842Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","migration_id":"93b51eee-a73a-4b20-a710-65377df3f566","target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4802026-01-06T01:22:50.765Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:51.261337247Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7854}}"}
4812026-01-06T01:22:52.637Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:53.134033201Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4822026-01-06T01:22:52.638Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:53.134095853Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","migration_id":"93b51eee-a73a-4b20-a710-65377df3f566","elapsed_milliseconds":4174,"target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4832026-01-06T01:22:52.662Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:53.135901602Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4842026-01-06T01:22:52.662Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:53.136073497Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4852026-01-06T01:22:52.662Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:53.136135299Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4862026-01-06T01:22:52.662Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:53.137155867Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4872026-01-06T01:22:52.718Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:53.214541225Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","elapsed_milliseconds":78}
4882026-01-06T01:22:52.718Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:53.214646828Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":9366,"target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4892026-01-06T01:22:52.718Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:53.214700319Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1655f74f-299d-4397-9101-6100a1bab6f2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":9366,"target_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c"}
4902026-01-06T01:22:54.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.04581847Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e","elapsed_milliseconds":1909}
4912026-01-06T01:22:54.573Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.046132708Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4922026-01-06T01:22:54.574Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.046235681Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4932026-01-06T01:22:54.598Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.079058733Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e","elapsed_milliseconds":32}
4942026-01-06T01:22:54.598Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.079211788Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
4952026-01-06T01:22:54.598Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.079480275Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
4962026-01-06T01:22:54.598Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.079538397Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
4972026-01-06T01:22:54.598Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.079617019Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
4982026-01-06T01:22:54.598Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.07965258Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":18894}
4992026-01-06T01:22:54.598Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.08039297Z","target":"phd_framework::test_vm","line":1077,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
5002026-01-06T01:22:55.086Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.581855309Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
5012026-01-06T01:22:55.164Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.660207714Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
5022026-01-06T01:22:55.164Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.660268186Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-936fd65e-0c72-4eca-8588-77b5b8be65cf\"]","verb":"destroy","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
5032026-01-06T01:22:55.188Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.679894945Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
5042026-01-06T01:22:55.188Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.679940756Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-6bd6382f-6d91-455f-ae8b-512b61bf1dad\"]","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
5052026-01-06T01:22:55.212Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.693217061Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e","elapsed_milliseconds":613}
5062026-01-06T01:22:55.212Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.693338285Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":7201,"target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
5072026-01-06T01:22:55.212Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.693356645Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":613}
5082026-01-06T01:22:55.212Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.693387706Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6780680d-bcc8-4e2c-81bc-3e128258bc3c","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":7201,"target_id":"9a781ff1-f391-4d5e-a384-d4f1ae1b064e"}
5092026-01-06T01:22:55.212Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.693419607Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5102026-01-06T01:22:55.212Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.693423217Z","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":20031}
5112026-01-06T01:22:55.212Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.693459398Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5122026-01-06T01:22:55.212Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 113.49s
5132026-01-06T01:22:55.212Z
5142026-01-06T01:22:55.212Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"buskin","pid":863,"time":"2026-01-06T01:22:55.69353344Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5152026-01-06T01:22:55.279Z
5162026-01-06T01:22:55.303Zreal 1:54.418837474
5172026-01-06T01:22:55.303Zuser 37.907612477
5182026-01-06T01:22:55.303Zsys 16.150958599
5192026-01-06T01:22:55.303Ztrap 0.004068437
5202026-01-06T01:22:55.303Ztflt 0.001526391
5212026-01-06T01:22:55.303Zdflt 0.000889550
5222026-01-06T01:22:55.303Zkflt 0.000160243
5232026-01-06T01:22:55.303Zlock 1:50:46.120212775
5242026-01-06T01:22:55.303Zslp 4:28.515083423
5252026-01-06T01:22:55.303Zlat 1.000876018
5262026-01-06T01:22:55.303Zstop 9.879920835
5272026-01-06T01:22:55.303Z+ failcount=0
5282026-01-06T01:22:55.303Z+ set -e
5292026-01-06T01:22:55.303Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log /tmp/propolis-phd/migration_from_base_and_back.serial.log /tmp/propolis-phd/migration_from_base_and_back.stderr.log /tmp/propolis-phd/migration_from_base_and_back.stdout.log /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log /tmp/propolis-phd/migration_from_base.serial.log /tmp/propolis-phd/migration_from_base.stderr.log /tmp/propolis-phd/migration_from_base.stdout.log /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log /tmp/propolis-phd/migration_serial_history_base.serial.log /tmp/propolis-phd/migration_serial_history_base.stderr.log /tmp/propolis-phd/migration_serial_history_base.stdout.log
5302026-01-06T01:22:55.303ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5312026-01-06T01:22:55.303Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5322026-01-06T01:22:55.303Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log 232K
5332026-01-06T01:22:55.303Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5342026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log 232K
5352026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5362026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log 145K
5372026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base_and_back.serial.log 7K
5382026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base_and_back.stderr.log 0K
5392026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base_and_back.stdout.log 139K
5402026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log 0K
5412026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log 145K
5422026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base.serial.log 7K
5432026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base.stderr.log 0K
5442026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_from_base.stdout.log 139K
5452026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log 0K
5462026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log 146K
5472026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_serial_history_base.serial.log 7K
5482026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_serial_history_base.stderr.log 0K
5492026-01-06T01:22:55.304Za /tmp/propolis-phd/migration_serial_history_base.stdout.log 140K
5502026-01-06T01:22:55.304Z+ exitcode=0
5512026-01-06T01:22:55.304Z+ '[' 0 -eq 0 ']'
5522026-01-06T01:22:55.304Z+ echo
5532026-01-06T01:22:55.304Z
5542026-01-06T01:22:55.304Z+ echo 'ALL TESTS PASSED'
5552026-01-06T01:22:55.304ZALL TESTS PASSED
5562026-01-06T01:22:55.304Z
5572026-01-06T01:22:55.304Z+ echo
5582026-01-06T01:22:55.304Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5592026-01-06T01:22:55.304Z+ read
5602026-01-06T01:22:55.304Z+ exit 0
5612026-01-06T01:22:55.304Zprocess exited: duration 127901 ms, exit code 0
 
5622026-01-06T01:22:55.353Zfound 2 output files
5632026-01-06T01:22:55.353Zuploading: /tmp/phd-runner.log (163544 bytes)
5642026-01-06T01:22:56.516Zuploaded: /tmp/phd-runner.log
5652026-01-06T01:22:56.516Zuploading: /tmp/phd-tmp-files.tar.gz (104943 bytes)
5662026-01-06T01:22:57.718Zuploaded: /tmp/phd-tmp-files.tar.gz