01KB34WJJKY5127JGQ1NW1BQY6: 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: 01KB34WSC1B549P0VKV8TEJB8R

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-11-27T17:25:53.365Zjob dependencies complete; ready to run (waiting for 12 m 15 s)
22025-11-27T17:43:01.196Zjob assigned to worker 01KB36CENJ84HT4ASEP5F3P0R7 [factory lab, buskin/17778] (queued for 17 m 7 s)
32025-11-27T17:43:01.303Zhttp://172.20.0.5:9969/ipxe/buskin... ok
42025-11-27T17:43:01.372Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/kernel/amd64/unix... ok
52025-11-27T17:43:01.405Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive... ok
62025-11-27T17:43:01.455Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive.hash... ok
72025-11-27T17:43:01.489Zhttp://172.20.0.5:9969/postboot/buskin... ok
82025-11-27T17:43:01.522ZwcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U
92025-11-27T17:43:01.556Zcpu0: microcode has been updated from version 0xa001133 to 0xa0011d5
102025-11-27T17:43:01.589ZOxide Helios Version helios-2.0.23457 64-bit
112025-11-27T17:43:01.623ZConfiguring devices.
122025-11-27T17:43:01.656Z##################################################
132025-11-27T17:43:01.689Z#### ############# ##
142025-11-27T17:43:01.723Z### ### ############ ##
152025-11-27T17:43:01.756Z## ### # ## ### ## Oxide Computer Company ##
162025-11-27T17:43:01.790Z## ## ## ### # ### ##
172025-11-27T17:43:01.823Z## # ### #### #### This Station Under ##
182025-11-27T17:43:01.857Z### ### #### # ### Computer Control ##
192025-11-27T17:43:01.890Z#### #### ### ## ##
202025-11-27T17:43:01.924Z##################################################
212025-11-27T17:43:01.957ZHostname: buskin
222025-11-27T17:43:01.991ZLoading smf(7) service descriptions:
232025-11-27T17:43:02.187Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
242025-11-27T17:43:02.212Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
252025-11-27T17:43:02.212Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
262025-11-27T17:43:02.243Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
272025-11-27T17:43:02.243Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
282025-11-27T17:43:49.259Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
292025-11-27T17:43:49.259Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
302025-11-27T17:43:49.325Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
312025-11-27T17:43:49.325Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
322025-11-27T17:45:01.821Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
332025-11-27T17:45:01.821Zstarting task 0: "setup"
342025-11-27T17:45:01.846Z++ uname -s
352025-11-27T17:45:01.846Z+ kern=SunOS
362025-11-27T17:45:01.846Z+ build_user=build
372025-11-27T17:45:01.846Z+ build_uid=12345
382025-11-27T17:45:01.846Z+ work_dir=/work
392025-11-27T17:45:01.846Z+ input_dir=/input
402025-11-27T17:45:01.846Z+ [[ 0 == 12345 ]]
412025-11-27T17:45:01.846Z+ case "$kern" in
422025-11-27T17:45:01.846Z+ groupadd -g 12345 build
432025-11-27T17:45:01.846Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
442025-11-27T17:45:03.841Z+ zfs create -o mountpoint=/work rpool/work
452025-11-27T17:45:03.866Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
462025-11-27T17:45:03.890Z+ home_fs=zfs
472025-11-27T17:45:03.890Z+ [[ zfs == autofs ]]
482025-11-27T17:45:03.890Z+ mkdir -p /home/build
492025-11-27T17:45:03.890Z+ chown build:build /home/build /work
502025-11-27T17:45:05.872Z+ chmod 0700 /home/build /work
512025-11-27T17:45:05.897Zprocess exited: duration 4053 ms, exit code 0
 
522025-11-27T17:45:05.946Zstarting task 1: "authentication"
532025-11-27T17:45:05.992Zprocess exited: duration 45 ms, exit code 0
 
542025-11-27T17:45:06.041Zstarting task 2: "build"
552025-11-27T17:45:06.066Z+ indir=/input
562025-11-27T17:45:06.066Z+ indir_suffix='phd-build/out/*.tar.gz'
572025-11-27T17:45:06.066Z+ phddir=/work/phd-test
582025-11-27T17:45:06.066Z+ pfexec zpool create -f phd-artifacts c1t1d0 c2t1d0
592025-11-27T17:45:06.232Z+ artifactdir=/phd-artifacts
602025-11-27T17:45:06.232Z+ banner Inputs
612025-11-27T17:45:06.257Z ###
622025-11-27T17:45:06.257Z # # # ##### # # ##### ####
632025-11-27T17:45:06.257Z # ## # # # # # # #
642025-11-27T17:45:06.257Z # # # # # # # # # ####
652025-11-27T17:45:06.257Z # # # # ##### # # # #
662025-11-27T17:45:06.257Z # # ## # # # # # #
672025-11-27T17:45:06.257Z ### # # # #### # ####
682025-11-27T17:45:06.257Z
692025-11-27T17:45:06.257Z+ find /input -ls
702025-11-27T17:45:06.257Z 34 1 drwxr-xr-x 3 root root 3 Nov 27 17:43 /input
712025-11-27T17:45:06.257Z 2 1 drwxr-xr-x 3 root root 3 Nov 27 17:43 /input/phd-build
722025-11-27T17:45:06.257Z 3 2 drwxr-xr-x 2 root root 7 Nov 27 17:43 /input/phd-build/out
732025-11-27T17:45:06.257Z 129 1 -rw-r--r-- 1 root root 65 Nov 27 17:43 /input/phd-build/out/phd-runner.sha256.txt
742025-11-27T17:45:06.257Z 257 168073 -rw-r--r-- 1 root root 171993952 Nov 27 17:45 /input/phd-build/out/propolis-server-debug.tar.gz
752025-11-27T17:45:06.257Z 130 104131 -rw-r--r-- 1 root root 106551449 Nov 27 17:43 /input/phd-build/out/phd-runner.tar.gz
762025-11-27T17:45:06.257Z 256 1 -rw-r--r-- 1 root root 65 Nov 27 17:43 /input/phd-build/out/propolis-server-debug.sha256.txt
772025-11-27T17:45:06.257Z 128 3 -rw-r--r-- 1 root root 2402 Nov 27 17:43 /input/phd-build/out/phd-run-with-args.sh
782025-11-27T17:45:06.257Z+ rm -rf /work/phd-test
792025-11-27T17:45:06.257Z+ mkdir /work/phd-test
802025-11-27T17:45:06.257Z+ for p in $indir/$indir_suffix
812025-11-27T17:45:06.257Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
822025-11-27T17:45:08.846ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
832025-11-27T17:45:08.846Zx phd-runner, 378502816 bytes, 739264 tape blocks
842025-11-27T17:45:08.846Zx artifacts.toml, 548 bytes, 2 tape blocks
852025-11-27T17:45:08.871Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
862025-11-27T17:45:11.016Z+ for f in $(tar tf "$p")
872025-11-27T17:45:11.016Z+ chmod +x /work/phd-test/phd-runner
882025-11-27T17:45:11.041Z+ for f in $(tar tf "$p")
892025-11-27T17:45:11.041Z+ chmod +x /work/phd-test/artifacts.toml
902025-11-27T17:45:11.041Z+ for p in $indir/$indir_suffix
912025-11-27T17:45:11.041Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
922025-11-27T17:45:15.049ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
932025-11-27T17:45:15.049Zx propolis-server, 656187160 bytes, 1281616 tape blocks
942025-11-27T17:45:15.073Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
952025-11-27T17:45:18.666Z+ for f in $(tar tf "$p")
962025-11-27T17:45:18.666Z+ chmod +x /work/phd-test/propolis-server
972025-11-27T17:45:18.690Z+ ls /work/phd-test
982025-11-27T17:45:18.690Zartifacts.toml
992025-11-27T17:45:18.690Zphd-runner
1002025-11-27T17:45:18.690Zpropolis-server
1012025-11-27T17:45:18.690Z+ banner Setup
1022025-11-27T17:45:18.690Z #####
1032025-11-27T17:45:18.690Z# # ###### ##### # # #####
1042025-11-27T17:45:18.690Z# # # # # # #
1052025-11-27T17:45:18.691Z ##### ##### # # # # #
1062025-11-27T17:45:18.691Z # # # # # #####
1072025-11-27T17:45:18.691Z# # # # # # #
1082025-11-27T17:45:18.691Z ##### ###### # #### #
1092025-11-27T17:45:18.691Z
1102025-11-27T17:45:18.691Z+ tmpdir=/tmp/propolis-phd
1112025-11-27T17:45:18.691Z+ '[' '!' -d /tmp/propolis-phd ']'
1122025-11-27T17:45:18.691Z+ mkdir /tmp/propolis-phd
1132025-11-27T17:45:18.691Z+ pfexec /usr/lib/rsrvrctl -s 4096
1142025-11-27T17:45:19.280Z+ banner Tests
1152025-11-27T17:45:19.305Z#######
1162025-11-27T17:45:19.305Z # ###### #### ##### ####
1172025-11-27T17:45:19.305Z # # # # #
1182025-11-27T17:45:19.305Z # ##### #### # ####
1192025-11-27T17:45:19.305Z # # # # #
1202025-11-27T17:45:19.305Z # # # # # # #
1212025-11-27T17:45:19.305Z # ###### #### # ####
1222025-11-27T17:45:19.305Z
1232025-11-27T17:45:19.305Z+ runner=/work/phd-test/phd-runner
1242025-11-27T17:45:19.305Z+ artifacts=/work/phd-test/artifacts.toml
1252025-11-27T17:45:19.305Z+ propolis=/work/phd-test/propolis-server
1262025-11-27T17:45:19.305Z+ ls /work/phd-test/phd-runner
1272025-11-27T17:45:19.305Z/work/phd-test/phd-runner
1282025-11-27T17:45:19.305Z+ ls /work/phd-test/artifacts.toml
1292025-11-27T17:45:19.305Z/work/phd-test/artifacts.toml
1302025-11-27T17:45:19.305Z+ ls /work/phd-test/propolis-server
1312025-11-27T17:45:19.305Z/work/phd-test/propolis-server
1322025-11-27T17:45:19.305Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1332025-11-27T17:45:19.305Z+ set +e
1342025-11-27T17:45:19.306Z+ RUST_BACKTRACE=1
1352025-11-27T17:45:19.306Z+ RUST_LOG=info,phd=debug
1362025-11-27T17:45:19.306Z+ 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
1372025-11-27T17:45:19.306Z+ tee /tmp/phd-runner.log
1382025-11-27T17:45:19.330Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:19.689915509Z","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 }"}
1392025-11-27T17:45:19.330Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:19.692787657Z","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: 433, tv_nsec: 191576929 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1402025-11-27T17:45:19.330Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:19.692872719Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1412025-11-27T17:45:19.330Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:19.693038052Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"7103cd3a3d7b0112d2949dd135db06fef0c156bb"}
1422025-11-27T17:45:19.330Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:19.693276607Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/7103cd3a3d7b0112d2949dd135db06fef0c156bb/crucible-nightly.sha256.txt","timeout":"600s"}
1432025-11-27T17:45:19.604Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:19.975855112Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1442025-11-27T17:45:20.128Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.499441305Z","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/cae89ab26cf66244fa3cd6796d17ce5c5049c928/propolis-server.sha256.txt","timeout":"600s"}
1452025-11-27T17:45:20.239Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.610532638Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1462025-11-27T17:45:20.775Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.610736942Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1472025-11-27T17:45:20.775Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.610967477Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1482025-11-27T17:45:20.775Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.611014268Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1492025-11-27T17:45:20.775Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.611042338Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1502025-11-27T17:45:20.775Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.611072029Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1512025-11-27T17:45:20.775Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.611371235Z","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"}
1522025-11-27T17:45:20.775Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.611877885Z","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"}
1532025-11-27T17:45:20.775Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:20.61213431Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/907a5fd1763ce5ddd74001261e5b52cd200a25f9/OVMF_CODE.fd","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1542025-11-27T17:45:21.047Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:21.419073174Z","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"}
1552025-11-27T17:45:21.072Z{"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":"2025-11-27T17:45:21.419259658Z","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"}
1562025-11-27T17:45:48.675Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.046574424Z","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"}
1572025-11-27T17:45:48.675Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.046685446Z","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"}
1582025-11-27T17:45:48.700Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.054488084Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2M 1.80T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1592025-11-27T17:45:48.700Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.054685958Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-d2e437da-011b-464e-a1b5-80a78753efeb\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1602025-11-27T17:45:48.736Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.107713189Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-d2e437da-011b-464e-a1b5-80a78753efeb\", \"phd-artifacts/phd-clone-95130b4d-bec4-417a-9ca1-bd0bc5b114b2\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1612025-11-27T17:45:48.761Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.123923606Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-95130b4d-bec4-417a-9ca1-bd0bc5b114b2\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1622025-11-27T17:45:48.761Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.130377516Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-95130b4d-bec4-417a-9ca1-bd0bc5b114b2 0B 1.80T 48.9M /phd-artifacts/phd-clone-95130b4d-bec4-417a-9ca1-bd0bc5b114b2\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632025-11-27T17:45:48.761Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.131122631Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1642025-11-27T17:45:48.761Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.131222533Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652025-11-27T17:45:48.761Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.131278325Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/9d852e24a78b0410e59a12205fbdc7a20c3f83a28197db6a973443d14ab7adc9/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1662025-11-27T17:45:48.761Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:45:49.131335066Z","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/cae89ab26cf66244fa3cd6796d17ce5c5049c928/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1672025-11-27T17:46:19.686Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:20.057525762Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/9d852e24a78b0410e59a12205fbdc7a20c3f83a28197db6a973443d14ab7adc9/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1682025-11-27T17:46:19.686Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:20.057604384Z","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"}
1692025-11-27T17:46:35.559Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:35.930067936Z","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/9d852e24a78b0410e59a12205fbdc7a20c3f83a28197db6a973443d14ab7adc9/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1702025-11-27T17:46:35.559Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:35.930177938Z","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"}
1712025-11-27T17:46:35.612Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 868","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:35.983199528Z","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"}
1722025-11-27T17:46:35.637Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:35.983658898Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1732025-11-27T17:46:35.637Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:35.984592977Z","target":"phd_framework::test_vm","line":345,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1742025-11-27T17:46:35.637Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:35.984903393Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":46853}
1752025-11-27T17:46:35.960Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.33142311Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1762025-11-27T17:46:35.985Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.332190185Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: a7fa8e62-834f-445d-a907-e0f0ba83a6f9, metadata: InstanceMetadata { project_id: 5fe8bde6-cea5-4578-afbc-7f4fe64e7425, silo_id: 0c377ae4-eae6-44af-8315-18a5dea6531f, sled_id: 14b53a5e-c520-4955-9c30-c73ac76f477d, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"14b53a5e-c520-4955-9c30-c73ac76f477d\" }, name: \"phd-vm-a7fa8e62-834f-445d-a907-e0f0ba83a6f9\" }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1772025-11-27T17:46:35.985Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.332327098Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1782025-11-27T17:46:35.985Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.332374259Z","target":"phd_framework::test_vm","line":470,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1792025-11-27T17:46:35.985Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.333162715Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":0}
1802025-11-27T17:46:35.985Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.333273667Z","target":"phd_framework::test_vm","line":780,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1812025-11-27T17:46:35.985Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.333322588Z","target":"phd_framework::test_vm","line":729,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1822025-11-27T17:46:35.985Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.333362029Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1832025-11-27T17:46:35.985Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.333428661Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1842025-11-27T17:46:35.985Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:36.333481342Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1852025-11-27T17:46:40.435Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.805540103Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4472}
1862025-11-27T17:46:40.435Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.805624694Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1872025-11-27T17:46:40.459Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.805935511Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1882025-11-27T17:46:40.459Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.805987362Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1892025-11-27T17:46:40.459Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.806029783Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1902025-11-27T17:46:40.459Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.82421687Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":18}
1912025-11-27T17:46:40.460Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.824305122Z","target":"phd_framework::test_vm","line":737,"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"}
1922025-11-27T17:46:40.460Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.824486005Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1932025-11-27T17:46:40.460Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.824538636Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1942025-11-27T17:46:40.460Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.824579997Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1952025-11-27T17:46:40.486Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.85742788Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32}
1962025-11-27T17:46:40.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.857504702Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1972025-11-27T17:46:40.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.857550083Z","target":"phd_framework::test_vm","line":780,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4524}
1982025-11-27T17:46:40.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.857699976Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
1992025-11-27T17:46:40.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.857757207Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2002025-11-27T17:46:40.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.868137757Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10}
2012025-11-27T17:46:40.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.86831541Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2022025-11-27T17:46:40.511Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.868374252Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2032025-11-27T17:46:40.536Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.90144918Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":33}
2042025-11-27T17:46:40.536Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.901693484Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2052025-11-27T17:46:40.536Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.901782226Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2062025-11-27T17:46:40.561Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.912195977Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10}
2072025-11-27T17:46:40.561Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.912339839Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2082025-11-27T17:46:40.561Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.91239689Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2092025-11-27T17:46:40.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.945455188Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":33}
2102025-11-27T17:46:40.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.945678482Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2112025-11-27T17:46:40.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.945764194Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2122025-11-27T17:46:40.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.956279097Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10}
2132025-11-27T17:46:40.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.956484041Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2142025-11-27T17:46:40.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.956568893Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2152025-11-27T17:46:40.618Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.989465486Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32}
2162025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.98963798Z","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"}
2172025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.989732451Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2182025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.989794463Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2192025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.989874504Z","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"}
2202025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.989937075Z","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"}
2212025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.989989717Z","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::can_migrate_from_base"}
2222025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:40.990033737Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2232025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 869","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:41.011308747Z","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"}
2242025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:41.011568042Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":21}
2252025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:41.011667764Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2262025-11-27T17:46:40.666Z{"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":"2025-11-27T17:46:41.011744176Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"0d27a3ba-2a1d-4659-8a74-56a9407b8398","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2272025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:41.011818947Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2282025-11-27T17:46:40.666Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:41.012420729Z","target":"phd_framework::test_vm","line":345,"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":"a36dfe67-a333-47f8-aa3c-183003b75046","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2292025-11-27T17:46:40.965Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:41.336017374Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: a36dfe67-a333-47f8-aa3c-183003b75046, metadata: InstanceMetadata { project_id: 5fe8bde6-cea5-4578-afbc-7f4fe64e7425, silo_id: 0c377ae4-eae6-44af-8315-18a5dea6531f, sled_id: 6e621945-8f05-43d3-8f60-c103edf1362d, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"6e621945-8f05-43d3-8f60-c103edf1362d\" }, name: \"phd-vm-a36dfe67-a333-47f8-aa3c-183003b75046\" }, state: Migrating }","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2302025-11-27T17:46:40.965Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:41.336205298Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"0d27a3ba-2a1d-4659-8a74-56a9407b8398","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2312025-11-27T17:46:43.212Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.582564457Z","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}}"}
2322025-11-27T17:46:43.510Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.881146316Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2332025-11-27T17:46:43.510Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.881201237Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":2544,"migration_id":"0d27a3ba-2a1d-4659-8a74-56a9407b8398","target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2342025-11-27T17:46:43.535Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.882834881Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2352025-11-27T17:46:43.535Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.883080975Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2362025-11-27T17:46:43.535Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.883132996Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2372025-11-27T17:46:43.535Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.884356051Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2382025-11-27T17:46:43.584Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.955316734Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":72}
2392025-11-27T17:46:43.609Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.955466227Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":7971}
2402025-11-27T17:46:43.609Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.9556075Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":72}
2412025-11-27T17:46:43.609Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.955817294Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2422025-11-27T17:46:43.609Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.955885946Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2432025-11-27T17:46:43.634Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.982437821Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":26}
2442025-11-27T17:46:43.634Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.982537743Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2452025-11-27T17:46:43.634Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.982691066Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2462025-11-27T17:46:43.634Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.982797748Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":7651}
2472025-11-27T17:46:43.634Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.98289652Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
2482025-11-27T17:46:43.634Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.982971592Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2492025-11-27T17:46:43.634Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:43.98386407Z","target":"phd_framework::test_vm","line":1075,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2502025-11-27T17:46:43.927Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.298238568Z","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::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2512025-11-27T17:46:44.001Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.371775433Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2522025-11-27T17:46:44.001Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.371833864Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-95130b4d-bec4-417a-9ca1-bd0bc5b114b2\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2532025-11-27T17:46:44.028Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.398639096Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2542025-11-27T17:46:44.028Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.398695046Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-d2e437da-011b-464e-a1b5-80a78753efeb\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046"}
2552025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.413886923Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":431}
2562025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.414113748Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":431}
2572025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.414121228Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"a36dfe67-a333-47f8-aa3c-183003b75046","target":"migration_from_base_lifecycle_0","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9","vm":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","elapsed_milliseconds":3402}
2582025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.41419217Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3402,"target":"migration_from_base_lifecycle_0","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"a36dfe67-a333-47f8-aa3c-183003b75046","source_id":"a7fa8e62-834f-445d-a907-e0f0ba83a6f9"}
2592025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.41420584Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
2602025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.41423512Z","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":83802}
2612025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.414247001Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2622025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.414285711Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2632025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.414401524Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2642025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.414497116Z","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"}
2652025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.414553357Z","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"}
2662025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.414602798Z","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"}
2672025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.414663359Z","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"}
2682025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.421546328Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 840M 1.80T 839M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2692025-11-27T17:46:44.075Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.42163674Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-18bf90c3-aece-4930-aa04-d57c862101ac\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::serial_history"}
2702025-11-27T17:46:44.100Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.435060571Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-18bf90c3-aece-4930-aa04-d57c862101ac\", \"phd-artifacts/phd-clone-aa0a43da-ce2e-4743-89ff-936b9f02dc87\"]","path":"phd_tests::migrate::from_base::serial_history"}
2712025-11-27T17:46:44.100Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.452450292Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-aa0a43da-ce2e-4743-89ff-936b9f02dc87\"]","path":"phd_tests::migrate::from_base::serial_history"}
2722025-11-27T17:46:44.100Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.458503204Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-aa0a43da-ce2e-4743-89ff-936b9f02dc87 0B 1.80T 839M /phd-artifacts/phd-clone-aa0a43da-ce2e-4743-89ff-936b9f02dc87\n","path":"phd_tests::migrate::from_base::serial_history"}
2732025-11-27T17:46:44.100Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.459101316Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2742025-11-27T17:46:44.100Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.459152037Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_serial_history_base","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
2752025-11-27T17:46:44.100Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.459196188Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/9d852e24a78b0410e59a12205fbdc7a20c3f83a28197db6a973443d14ab7adc9/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2762025-11-27T17:46:44.100Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.459246649Z","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/9d852e24a78b0410e59a12205fbdc7a20c3f83a28197db6a973443d14ab7adc9/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
2772025-11-27T17:46:44.100Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.45929198Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/migration_serial_history_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_serial_history_base.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2782025-11-27T17:46:44.125Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 878","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.47907197Z","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"}
2792025-11-27T17:46:44.125Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.479323185Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":20}
2802025-11-27T17:46:44.125Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.479410976Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2812025-11-27T17:46:44.125Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:44.48006836Z","target":"phd_framework::test_vm","line":345,"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":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2822025-11-27T17:46:44.866Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.237013644Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2832025-11-27T17:46:44.891Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.237765249Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: d7be701d-6240-40ea-aeb6-e62a0234ad83, metadata: InstanceMetadata { project_id: aa8c3180-7a41-4913-a160-7054639f6bde, silo_id: cd1cd3cb-e5f4-4e5c-bfb2-c25c3e50c336, sled_id: 7e12a61a-d708-41db-89c5-07cf80913dc3, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"7e12a61a-d708-41db-89c5-07cf80913dc3\" }, name: \"phd-vm-d7be701d-6240-40ea-aeb6-e62a0234ad83\" }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2842025-11-27T17:46:44.891Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.237937652Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2852025-11-27T17:46:44.891Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.238000514Z","target":"phd_framework::test_vm","line":470,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2862025-11-27T17:46:44.891Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.239151797Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":1,"vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2872025-11-27T17:46:44.891Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.239248539Z","target":"phd_framework::test_vm","line":780,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2882025-11-27T17:46:44.891Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.23931388Z","target":"phd_framework::test_vm","line":729,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","timeout_duration":"300s","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","path":"phd_tests::migrate::from_base::serial_history"}
2892025-11-27T17:46:44.891Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.239371181Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
2902025-11-27T17:46:44.891Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.239422112Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2912025-11-27T17:46:44.891Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:45.239479143Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2922025-11-27T17:46:49.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.64144235Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4401,"vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2932025-11-27T17:46:49.270Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.641524432Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
2942025-11-27T17:46:49.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.641700355Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
2952025-11-27T17:46:49.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.641750096Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2962025-11-27T17:46:49.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.641787467Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2972025-11-27T17:46:49.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.659931743Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":18,"vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
2982025-11-27T17:46:49.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.660084617Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
2992025-11-27T17:46:49.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.660350632Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3002025-11-27T17:46:49.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.660403053Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3012025-11-27T17:46:49.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.660443794Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3022025-11-27T17:46:49.323Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.69345466Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":32,"vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3032025-11-27T17:46:49.323Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.693558573Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3042025-11-27T17:46:49.347Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.693626254Z","target":"phd_framework::test_vm","line":780,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4454}
3052025-11-27T17:46:49.347Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.693850378Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3062025-11-27T17:46:49.347Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.69394476Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3072025-11-27T17:46:49.347Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.704510224Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":10,"vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3082025-11-27T17:46:49.347Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.704707058Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3092025-11-27T17:46:49.347Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.704766969Z","target":"phd_framework::test_vm","line":802,"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":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3102025-11-27T17:46:49.372Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.737681484Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":32,"vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3112025-11-27T17:46:49.372Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.742372218Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_serial_history_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::serial_history"}
3122025-11-27T17:46:49.372Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.7424437Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3132025-11-27T17:46:49.372Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.74248447Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_serial_history_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
3142025-11-27T17:46:49.372Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.742539642Z","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"}
3152025-11-27T17:46:49.372Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.742584252Z","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:9002","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
3162025-11-27T17:46:49.372Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.742638233Z","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"}
3172025-11-27T17:46:49.397Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 879","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.76376063Z","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"}
3182025-11-27T17:46:49.397Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.764034545Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":21}
3192025-11-27T17:46:49.397Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.764135448Z","target":"phd_framework::test_vm","line":499,"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":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","target_id":"63123c30-5261-4f5c-96bc-633db99922fd"}
3202025-11-27T17:46:49.397Z{"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":"2025-11-27T17:46:49.764223699Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"0603474c-06d3-4239-b5da-de6ca05b8a69","timeout_duration":"45s","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","target_id":"63123c30-5261-4f5c-96bc-633db99922fd"}
3212025-11-27T17:46:49.397Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.764328751Z","target":"phd_framework::test_vm","line":306,"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":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base_lifecycle_0","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","target_id":"63123c30-5261-4f5c-96bc-633db99922fd"}
3222025-11-27T17:46:49.397Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:49.764780501Z","target":"phd_framework::test_vm","line":345,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base_lifecycle_0","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","target_id":"63123c30-5261-4f5c-96bc-633db99922fd"}
3232025-11-27T17:46:49.767Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:50.138366454Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 63123c30-5261-4f5c-96bc-633db99922fd, metadata: InstanceMetadata { project_id: aa8c3180-7a41-4913-a160-7054639f6bde, silo_id: cd1cd3cb-e5f4-4e5c-bfb2-c25c3e50c336, sled_id: 3796cdb1-f8df-4087-804a-f711936134b2, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"3796cdb1-f8df-4087-804a-f711936134b2\" }, name: \"phd-vm-63123c30-5261-4f5c-96bc-633db99922fd\" }, state: Migrating }","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base_lifecycle_0","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","target_id":"63123c30-5261-4f5c-96bc-633db99922fd"}
3242025-11-27T17:46:49.792Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:50.138522687Z","target":"phd_framework::test_vm","line":553,"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":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","target_id":"63123c30-5261-4f5c-96bc-633db99922fd","migration_id":"0603474c-06d3-4239-b5da-de6ca05b8a69"}
3252025-11-27T17:46:51.803Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.173984157Z","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}}"}
3262025-11-27T17:46:52.014Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.384409116Z","target":"phd_framework::test_vm","line":566,"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":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","target_id":"63123c30-5261-4f5c-96bc-633db99922fd"}
3272025-11-27T17:46:52.014Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.384515018Z","target":"phd_framework::test_vm","line":553,"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":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","elapsed_milliseconds":2245,"target_id":"63123c30-5261-4f5c-96bc-633db99922fd","migration_id":"0603474c-06d3-4239-b5da-de6ca05b8a69"}
3282025-11-27T17:46:52.039Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.386466217Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3292025-11-27T17:46:52.039Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.387870506Z","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":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3302025-11-27T17:46:52.088Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.458775557Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":71,"vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3312025-11-27T17:46:52.113Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.458957491Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":7979,"vm_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base"}
3322025-11-27T17:46:52.113Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.461220647Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","vm":"migration_serial_history_base_lifecycle_0"}
3332025-11-27T17:46:52.113Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.46138158Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3342025-11-27T17:46:52.113Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.461459642Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3352025-11-27T17:46:52.113Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.461488832Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":7224}
3362025-11-27T17:46:52.113Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.461535233Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3372025-11-27T17:46:52.113Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:52.462446462Z","target":"phd_framework::test_vm","line":1075,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","vm":"migration_serial_history_base_lifecycle_0"}
3382025-11-27T17:46:52.776Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.146137607Z","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":"63123c30-5261-4f5c-96bc-633db99922fd","vm":"migration_serial_history_base_lifecycle_0"}
3392025-11-27T17:46:52.843Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.214001517Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","vm":"migration_serial_history_base_lifecycle_0"}
3402025-11-27T17:46:52.843Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.214060718Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-aa0a43da-ce2e-4743-89ff-936b9f02dc87\"]","verb":"destroy","path":"phd_tests::migrate::from_base::serial_history","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","vm":"migration_serial_history_base_lifecycle_0"}
3412025-11-27T17:46:52.868Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.239291018Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","vm":"migration_serial_history_base_lifecycle_0"}
3422025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.239350509Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-18bf90c3-aece-4930-aa04-d57c862101ac\"]","verb":"destroy","path":"phd_tests::migrate::from_base::serial_history","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","vm":"migration_serial_history_base_lifecycle_0"}
3432025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.25823567Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":796,"vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","vm":"migration_serial_history_base_lifecycle_0"}
3442025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258357873Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":796}
3452025-11-27T17:46:52.915Z{"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":"2025-11-27T17:46:53.258415284Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3462025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258458305Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3472025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258487985Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3482025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258474025Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":3494,"source":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","vm":"migration_serial_history_base_lifecycle_0","vm_id":"63123c30-5261-4f5c-96bc-633db99922fd","target_id":"63123c30-5261-4f5c-96bc-633db99922fd"}
3492025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258559277Z","target":"phd_framework::test_vm","line":499,"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":"migration_serial_history_base","source_id":"d7be701d-6240-40ea-aeb6-e62a0234ad83","elapsed_milliseconds":3494,"target_id":"63123c30-5261-4f5c-96bc-633db99922fd"}
3502025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258607408Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":8844}
3512025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258610198Z","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"}
3522025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.25869602Z","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"}
3532025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258751471Z","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"}
3542025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258808562Z","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"}
3552025-11-27T17:46:52.915Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.258866853Z","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"}
3562025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.266121379Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 841M 1.80T 839M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3572025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.266209161Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-f490daf6-776d-4bdf-ba07-c10f7537273f\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3582025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.27953953Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-f490daf6-776d-4bdf-ba07-c10f7537273f\", \"phd-artifacts/phd-clone-6abfc1d2-0018-4117-b893-6358711c1594\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3592025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.295178236Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-6abfc1d2-0018-4117-b893-6358711c1594\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3602025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.302027735Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-6abfc1d2-0018-4117-b893-6358711c1594 0B 1.80T 839M /phd-artifacts/phd-clone-6abfc1d2-0018-4117-b893-6358711c1594\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3612025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.302577086Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3622025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.302631137Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back","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"}
3632025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.302678858Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/9d852e24a78b0410e59a12205fbdc7a20c3f83a28197db6a973443d14ab7adc9/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3642025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.302726579Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/9d852e24a78b0410e59a12205fbdc7a20c3f83a28197db6a973443d14ab7adc9/propolis-server\"","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3652025-11-27T17:46:52.941Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.30278404Z","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"}
3662025-11-27T17:46:52.966Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 888","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.323191452Z","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"}
3672025-11-27T17:46:52.966Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.323530259Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":20}
3682025-11-27T17:46:52.966Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.323662001Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3692025-11-27T17:46:52.966Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:53.324468418Z","target":"phd_framework::test_vm","line":345,"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","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3702025-11-27T17:46:53.701Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.07187782Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3712025-11-27T17:46:53.726Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.072477362Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: f33ec562-1615-449d-979b-b2fac3c0722c, metadata: InstanceMetadata { project_id: 298a8671-76dc-4922-935e-2fc7609c229b, silo_id: b29f221c-37ab-4b75-bb42-33089f3517ba, sled_id: 2eca2962-1418-4d4b-93fa-929a52928d8a, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"2eca2962-1418-4d4b-93fa-929a52928d8a\" }, name: \"phd-vm-f33ec562-1615-449d-979b-b2fac3c0722c\" }, state: Creating }","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3722025-11-27T17:46:53.726Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.072602155Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3732025-11-27T17:46:53.726Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.072650916Z","target":"phd_framework::test_vm","line":470,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3742025-11-27T17:46:53.726Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.073430291Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3752025-11-27T17:46:53.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.073500213Z","target":"phd_framework::test_vm","line":780,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762025-11-27T17:46:53.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.073547394Z","target":"phd_framework::test_vm","line":729,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772025-11-27T17:46:53.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.073586055Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782025-11-27T17:46:53.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.073620845Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792025-11-27T17:46:53.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:54.073663176Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802025-11-27T17:46:58.119Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.48993241Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4416,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3812025-11-27T17:46:58.119Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.490021472Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822025-11-27T17:46:58.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.490246086Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832025-11-27T17:46:58.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.490309998Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842025-11-27T17:46:58.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.490348778Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852025-11-27T17:46:58.145Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.509178199Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3862025-11-27T17:46:58.145Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.5092464Z","target":"phd_framework::test_vm","line":737,"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"}
3872025-11-27T17:46:58.145Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.509438284Z","target":"phd_framework::test_vm","line":737,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3882025-11-27T17:46:58.145Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.509503245Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3892025-11-27T17:46:58.145Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.509544346Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3902025-11-27T17:46:58.171Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.542154774Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3912025-11-27T17:46:58.171Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.542258336Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3922025-11-27T17:46:58.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.542323928Z","target":"phd_framework::test_vm","line":780,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4468}
3932025-11-27T17:46:58.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.542531282Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3942025-11-27T17:46:58.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.542580873Z","target":"phd_framework::test_vm","line":802,"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","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3952025-11-27T17:46:58.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.553913312Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962025-11-27T17:46:58.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.554128086Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972025-11-27T17:46:58.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.554214028Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3982025-11-27T17:46:58.222Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.587039091Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3992025-11-27T17:46:58.222Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.587270956Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4002025-11-27T17:46:58.222Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.587358287Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012025-11-27T17:46:58.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.597747827Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4022025-11-27T17:46:58.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.597966312Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4032025-11-27T17:46:58.247Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.598052743Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4042025-11-27T17:46:58.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.630660792Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4052025-11-27T17:46:58.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.630882626Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4062025-11-27T17:46:58.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.630976798Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4072025-11-27T17:46:58.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.641322107Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4082025-11-27T17:46:58.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.641552752Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4092025-11-27T17:46:58.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.641654704Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4102025-11-27T17:46:58.303Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.674381344Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4112025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.674501327Z","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"}
4122025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.674629209Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4132025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.674718191Z","target":"phd_framework::test_vm","line":215,"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_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4142025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.674820743Z","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"}
4152025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.674901405Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4162025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.674981967Z","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_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4172025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 889","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.696577033Z","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"}
4182025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.696906869Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":22}
4192025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.697011041Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4202025-11-27T17:46:58.352Z{"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":"2025-11-27T17:46:58.697098253Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"14efdb77-cbbe-4089-a339-d829dc8b93e7","source_id":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4212025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.697191705Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4222025-11-27T17:46:58.352Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:58.697830108Z","target":"phd_framework::test_vm","line":345,"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":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4232025-11-27T17:46:58.677Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:59.048331665Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e, metadata: InstanceMetadata { project_id: 298a8671-76dc-4922-935e-2fc7609c229b, silo_id: b29f221c-37ab-4b75-bb42-33089f3517ba, sled_id: db5ca435-faf4-497a-a0d7-0923cf74b388, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"db5ca435-faf4-497a-a0d7-0923cf74b388\" }, name: \"phd-vm-937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e\" }, state: Migrating }","source_id":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4242025-11-27T17:46:58.677Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:46:59.048470877Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"14efdb77-cbbe-4089-a339-d829dc8b93e7"}
4252025-11-27T17:47:00.928Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:01.299012532Z","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}}"}
4262025-11-27T17:47:01.376Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:01.747321174Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4272025-11-27T17:47:01.376Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:01.747381046Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":2698,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"14efdb77-cbbe-4089-a339-d829dc8b93e7"}
4282025-11-27T17:47:01.401Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:01.748813664Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4292025-11-27T17:47:01.401Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:01.748989408Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4302025-11-27T17:47:01.401Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:01.749052619Z","target":"phd_framework::test_vm","line":802,"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","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4312025-11-27T17:47:01.401Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:01.75007453Z","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","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4322025-11-27T17:47:01.449Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:01.819668165Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":70,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4332025-11-27T17:47:01.473Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:01.819820568Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":8496,"vm":"migration_from_base_and_back","vm_id":"f33ec562-1615-449d-979b-b2fac3c0722c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4342025-11-27T17:47:04.559Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.930066432Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3180,"vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4352025-11-27T17:47:04.559Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.930262736Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4362025-11-27T17:47:04.584Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.930329107Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4372025-11-27T17:47:04.609Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.963281142Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4382025-11-27T17:47:04.609Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.963366004Z","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"}
4392025-11-27T17:47:04.609Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.963448246Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4402025-11-27T17:47:04.609Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.963504967Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4412025-11-27T17:47:04.609Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.963577218Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/9d852e24a78b0410e59a12205fbdc7a20c3f83a28197db6a973443d14ab7adc9/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4422025-11-27T17:47:04.609Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.963640079Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9004","server_path":"\"/phd-artifacts/9d852e24a78b0410e59a12205fbdc7a20c3f83a28197db6a973443d14ab7adc9/propolis-server\"","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4432025-11-27T17:47:04.609Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.963697441Z","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_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4442025-11-27T17:47:04.634Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 891","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.985497411Z","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"}
4452025-11-27T17:47:04.634Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.985808437Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":22}
4462025-11-27T17:47:04.634Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.985896019Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","target_id":"5da12749-d102-4373-9593-885953e97066","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4472025-11-27T17:47:04.634Z{"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":"2025-11-27T17:47:04.98596944Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"839d9dc7-6aa8-4be6-8656-3d2f3b009196","source_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","target_id":"5da12749-d102-4373-9593-885953e97066","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4482025-11-27T17:47:04.634Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.986044232Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","target_id":"5da12749-d102-4373-9593-885953e97066","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4492025-11-27T17:47:04.634Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:04.986601193Z","target":"phd_framework::test_vm","line":345,"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":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","target_id":"5da12749-d102-4373-9593-885953e97066","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502025-11-27T17:47:05.197Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:05.567667547Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 5da12749-d102-4373-9593-885953e97066, metadata: InstanceMetadata { project_id: 298a8671-76dc-4922-935e-2fc7609c229b, silo_id: b29f221c-37ab-4b75-bb42-33089f3517ba, sled_id: faba1c10-c948-4d9f-a0e4-78907c9c3c8b, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"faba1c10-c948-4d9f-a0e4-78907c9c3c8b\" }, name: \"phd-vm-5da12749-d102-4373-9593-885953e97066\" }, state: Migrating }","source_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","target_id":"5da12749-d102-4373-9593-885953e97066","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512025-11-27T17:47:05.197Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:05.567790649Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","target_id":"5da12749-d102-4373-9593-885953e97066","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"839d9dc7-6aa8-4be6-8656-3d2f3b009196"}
4522025-11-27T17:47:07.449Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:07.820126869Z","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}}"}
4532025-11-27T17:47:08.422Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.792762968Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","target_id":"5da12749-d102-4373-9593-885953e97066","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542025-11-27T17:47:08.422Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.79285043Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","target_id":"5da12749-d102-4373-9593-885953e97066","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":3225,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"839d9dc7-6aa8-4be6-8656-3d2f3b009196"}
4552025-11-27T17:47:08.447Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.794656876Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4562025-11-27T17:47:08.447Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.79483503Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4572025-11-27T17:47:08.447Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.794901691Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4582025-11-27T17:47:08.447Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.796036854Z","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","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4592025-11-27T17:47:08.492Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.863069048Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":68,"vm":"migration_from_base_and_back_lifecycle_0","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4602025-11-27T17:47:08.517Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.863345343Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","vm_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source_id":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","elapsed_milliseconds":10166,"target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4612025-11-27T17:47:08.517Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.863467706Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"f33ec562-1615-449d-979b-b2fac3c0722c","source":"migration_from_base_and_back","target_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":10166,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4622025-11-27T17:47:08.559Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.929753434Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":134,"vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4632025-11-27T17:47:08.559Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.929953568Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4642025-11-27T17:47:08.583Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.9300466Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4652025-11-27T17:47:08.608Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.962665089Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4662025-11-27T17:47:08.608Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.96273563Z","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"}
4672025-11-27T17:47:08.608Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.962801522Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4682025-11-27T17:47:08.608Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.962866173Z","target":"phd_framework::test_vm","line":215,"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"}
4692025-11-27T17:47:08.608Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.962960185Z","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"}
4702025-11-27T17:47:08.608Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.963035336Z","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:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4712025-11-27T17:47:08.608Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.963110628Z","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"}
4722025-11-27T17:47:08.634Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 893","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.984692843Z","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"}
4732025-11-27T17:47:08.634Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.984951108Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":22}
4742025-11-27T17:47:08.634Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.98503983Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4752025-11-27T17:47:08.634Z{"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":"2025-11-27T17:47:08.985114361Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"1e5a2f3b-cdf0-462b-9011-38131eec6c53","timeout_duration":"45s","source_id":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762025-11-27T17:47:08.634Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.985184802Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772025-11-27T17:47:08.634Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:08.985668882Z","target":"phd_framework::test_vm","line":345,"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":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782025-11-27T17:47:09.181Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:09.551880146Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa, metadata: InstanceMetadata { project_id: 298a8671-76dc-4922-935e-2fc7609c229b, silo_id: b29f221c-37ab-4b75-bb42-33089f3517ba, sled_id: 61b1b844-5bd2-4d88-bb43-90ac39dcbf45, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"61b1b844-5bd2-4d88-bb43-90ac39dcbf45\" }, name: \"phd-vm-ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa\" }, state: Migrating }","source_id":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792025-11-27T17:47:09.205Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:09.552027139Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"1e5a2f3b-cdf0-462b-9011-38131eec6c53"}
4802025-11-27T17:47:11.441Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:11.811978083Z","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}}"}
4812025-11-27T17:47:12.807Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.177526506Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4822025-11-27T17:47:12.807Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.177588217Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":3625,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"1e5a2f3b-cdf0-462b-9011-38131eec6c53"}
4832025-11-27T17:47:12.831Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.179471805Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4842025-11-27T17:47:12.832Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.179654718Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4852025-11-27T17:47:12.832Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.179706219Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4862025-11-27T17:47:12.832Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.180789241Z","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","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4872025-11-27T17:47:12.881Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.251637742Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":71,"vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5da12749-d102-4373-9593-885953e97066","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4882025-11-27T17:47:12.906Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.251844856Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"5da12749-d102-4373-9593-885953e97066","vm_id":"5da12749-d102-4373-9593-885953e97066","source_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":8265,"target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4892025-11-27T17:47:12.906Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.251948258Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"937ab73d-ac6e-4ccd-9ba2-3b6af6149d7e","source":"migration_from_base_and_back_lifecycle_0","target_id":"5da12749-d102-4373-9593-885953e97066","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":8265,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4902025-11-27T17:47:12.906Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.251982389Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":72,"vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4912025-11-27T17:47:12.906Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.252186033Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4922025-11-27T17:47:12.906Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.252249354Z","target":"phd_framework::test_vm","line":802,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4932025-11-27T17:47:12.931Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.279691309Z","target":"phd_framework::test_vm","line":795,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":27,"vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4942025-11-27T17:47:12.931Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.27979272Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4952025-11-27T17:47:12.931Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.279943474Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
4962025-11-27T17:47:12.931Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.280041746Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":19208}
4972025-11-27T17:47:12.931Z{"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":"2025-11-27T17:47:13.280046896Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
4982025-11-27T17:47:12.931Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.280114367Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
4992025-11-27T17:47:12.931Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.280975364Z","target":"phd_framework::test_vm","line":1075,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5002025-11-27T17:47:13.276Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.646171469Z","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","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5012025-11-27T17:47:13.346Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.716765944Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5022025-11-27T17:47:13.346Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.716825725Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-6abfc1d2-0018-4117-b893-6358711c1594\"]","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5032025-11-27T17:47:13.374Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.745569716Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5042025-11-27T17:47:13.399Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.745626397Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-f490daf6-776d-4bdf-ba07-c10f7537273f\"]","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5052025-11-27T17:47:13.399Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.760743532Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":480,"vm":"migration_from_base_and_back_lifecycle_2","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062025-11-27T17:47:13.399Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.760837454Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","vm_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","source_id":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":4775,"target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5072025-11-27T17:47:13.399Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.760863695Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":480}
5082025-11-27T17:47:13.399Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.760883325Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"5da12749-d102-4373-9593-885953e97066","source":"migration_from_base_and_back_lifecycle_1","target_id":"ebf7d5db-bc70-4889-bbd6-5afd19b2c6aa","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":4775,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092025-11-27T17:47:13.399Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.760929376Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5102025-11-27T17:47:13.399Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.760928796Z","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":20502}
5112025-11-27T17:47:13.399Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.760969347Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5122025-11-27T17:47:13.399Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 113.15s
5132025-11-27T17:47:13.399Z
5142025-11-27T17:47:13.399Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"buskin","pid":863,"time":"2025-11-27T17:47:13.761047158Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5152025-11-27T17:47:13.464Z
5162025-11-27T17:47:13.489Zreal 1:54.096481891
5172025-11-27T17:47:13.489Zuser 37.050620575
5182025-11-27T17:47:13.489Zsys 15.897698701
5192025-11-27T17:47:13.489Ztrap 0.007948851
5202025-11-27T17:47:13.489Ztflt 0.002234584
5212025-11-27T17:47:13.489Zdflt 0.000579789
5222025-11-27T17:47:13.489Zkflt 0.000629830
5232025-11-27T17:47:13.489Zlock 1:49:41.087663592
5242025-11-27T17:47:13.489Zslp 4:18.400218886
5252025-11-27T17:47:13.489Zlat 1.013779350
5262025-11-27T17:47:13.489Zstop 8.128984023
5272025-11-27T17:47:13.489Z+ failcount=0
5282025-11-27T17:47:13.490Z+ set -e
5292025-11-27T17:47:13.490Z+ 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
5302025-11-27T17:47:13.490ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5312025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5322025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log 232K
5332025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5342025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log 232K
5352025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5362025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log 145K
5372025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_and_back.serial.log 7K
5382025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_and_back.stderr.log 0K
5392025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_and_back.stdout.log 139K
5402025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log 0K
5412025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log 145K
5422025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base.serial.log 7K
5432025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base.stderr.log 0K
5442025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_from_base.stdout.log 139K
5452025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log 0K
5462025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log 145K
5472025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_serial_history_base.serial.log 7K
5482025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_serial_history_base.stderr.log 0K
5492025-11-27T17:47:13.490Za /tmp/propolis-phd/migration_serial_history_base.stdout.log 139K
5502025-11-27T17:47:13.490Z+ exitcode=0
5512025-11-27T17:47:13.490Z+ '[' 0 -eq 0 ']'
5522025-11-27T17:47:13.490Z+ echo
5532025-11-27T17:47:13.490Z
5542025-11-27T17:47:13.490Z+ echo 'ALL TESTS PASSED'
5552025-11-27T17:47:13.490ZALL TESTS PASSED
5562025-11-27T17:47:13.490Z+ echo
5572025-11-27T17:47:13.490Z
5582025-11-27T17:47:13.490Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5592025-11-27T17:47:13.490Z+ read
5602025-11-27T17:47:13.490Z+ exit 0
5612025-11-27T17:47:13.490Zprocess exited: duration 127445 ms, exit code 0
 
5622025-11-27T17:47:13.566Zfound 2 output files
5632025-11-27T17:47:13.567Zuploading: /tmp/phd-runner.log (163545 bytes)
5642025-11-27T17:47:14.803Zuploaded: /tmp/phd-runner.log
5652025-11-27T17:47:14.803Zuploading: /tmp/phd-tmp-files.tar.gz (104853 bytes)
5662025-11-27T17:47:16.016Zuploaded: /tmp/phd-tmp-files.tar.gz