01K57J2XQG1R2MCE65DA6PDJTJ: 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: 01K57J3JR7K1E8A4GGHEMD2QJY

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-09-15T20:57:03.290Zjob dependencies complete; ready to run (waiting for 9 m 44 s)
22025-09-15T22:23:32.437Zjob assigned to worker 01K57QAYE6VX4JHNEBQQWRWSYC [factory lab, buskin/16738] (queued for 1 h 26 m 29 s)
32025-09-15T22:23:32.600Zhttp://172.20.0.5:9969/ipxe/buskin... ok
42025-09-15T22:23:32.666Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/kernel/amd64/unix... ok
52025-09-15T22:23:32.701Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive... ok
62025-09-15T22:23:32.734Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive.hash... ok
72025-09-15T22:23:32.768Zhttp://172.20.0.5:9969/postboot/buskin... ok
82025-09-15T22:23:32.801ZwcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U
92025-09-15T22:23:32.835Zcpu0: microcode has been updated from version 0xa001133 to 0xa0011d5
102025-09-15T22:23:32.868ZOxide Helios Version helios-2.0.23457 64-bit
112025-09-15T22:23:32.901ZConfiguring devices.
122025-09-15T22:23:32.935Z##################################################
132025-09-15T22:23:32.968Z#### ############# ##
142025-09-15T22:23:33.002Z### ### ############ ##
152025-09-15T22:23:33.035Z## ### # ## ### ## Oxide Computer Company ##
162025-09-15T22:23:33.070Z## ## ## ### # ### ##
172025-09-15T22:23:33.102Z## # ### #### #### This Station Under ##
182025-09-15T22:23:33.137Z### ### #### # ### Computer Control ##
192025-09-15T22:23:33.170Z#### #### ### ## ##
202025-09-15T22:23:33.204Z##################################################
212025-09-15T22:23:33.237ZHostname: buskin
222025-09-15T22:23:33.271ZLoading smf(7) service descriptions:
232025-09-15T22:23:34.250Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
242025-09-15T22:23:34.295Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
252025-09-15T22:23:34.295Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
262025-09-15T22:23:34.331Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
272025-09-15T22:23:34.331Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
282025-09-15T22:23:53.360Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
292025-09-15T22:23:53.360Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
302025-09-15T22:23:53.425Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
312025-09-15T22:23:53.450Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
322025-09-15T22:24:19.088Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
332025-09-15T22:24:19.114Zstarting task 0: "setup"
342025-09-15T22:24:19.114Z++ uname -s
352025-09-15T22:24:19.114Z+ kern=SunOS
362025-09-15T22:24:19.114Z+ build_user=build
372025-09-15T22:24:19.114Z+ build_uid=12345
382025-09-15T22:24:19.114Z+ work_dir=/work
392025-09-15T22:24:19.114Z+ input_dir=/input
402025-09-15T22:24:19.114Z+ [[ 0 == 12345 ]]
412025-09-15T22:24:19.114Z+ case "$kern" in
422025-09-15T22:24:19.114Z+ groupadd -g 12345 build
432025-09-15T22:24:19.114Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
442025-09-15T22:24:21.108Z+ zfs create -o mountpoint=/work rpool/work
452025-09-15T22:24:21.147Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
462025-09-15T22:24:21.171Z+ home_fs=zfs
472025-09-15T22:24:21.171Z+ [[ zfs == autofs ]]
482025-09-15T22:24:21.171Z+ mkdir -p /home/build
492025-09-15T22:24:21.171Z+ chown build:build /home/build /work
502025-09-15T22:24:23.155Z+ chmod 0700 /home/build /work
512025-09-15T22:24:23.180Zprocess exited: duration 4070 ms, exit code 0
 
522025-09-15T22:24:23.227Zstarting task 1: "authentication"
532025-09-15T22:24:23.273Zprocess exited: duration 45 ms, exit code 0
 
542025-09-15T22:24:23.321Zstarting task 2: "build"
552025-09-15T22:24:23.346Z+ indir=/input
562025-09-15T22:24:23.346Z+ indir_suffix='phd-build/out/*.tar.gz'
572025-09-15T22:24:23.346Z+ phddir=/work/phd-test
582025-09-15T22:24:23.346Z+ pfexec zpool create -f phd-artifacts c1t1d0 c2t1d0
592025-09-15T22:24:23.509Z+ artifactdir=/phd-artifacts
602025-09-15T22:24:23.509Z+ banner Inputs
612025-09-15T22:24:23.534Z ###
622025-09-15T22:24:23.534Z # # # ##### # # ##### ####
632025-09-15T22:24:23.534Z # ## # # # # # # #
642025-09-15T22:24:23.534Z # # # # # # # # # ####
652025-09-15T22:24:23.534Z # # # # ##### # # # #
662025-09-15T22:24:23.534Z # # ## # # # # # #
672025-09-15T22:24:23.534Z ### # # # #### # ####
682025-09-15T22:24:23.534Z
692025-09-15T22:24:23.534Z+ find /input -ls
702025-09-15T22:24:23.534Z 34 1 drwxr-xr-x 3 root root 3 Sep 15 22:23 /input
712025-09-15T22:24:23.534Z 2 1 drwxr-xr-x 3 root root 3 Sep 15 22:23 /input/phd-build
722025-09-15T22:24:23.534Z 3 2 drwxr-xr-x 2 root root 7 Sep 15 22:23 /input/phd-build/out
732025-09-15T22:24:23.534Z 130 106331 -rw-r--r-- 1 root root 108812869 Sep 15 22:23 /input/phd-build/out/phd-runner.tar.gz
742025-09-15T22:24:23.534Z 257 149643 -rw-r--r-- 1 root root 153131143 Sep 15 22:24 /input/phd-build/out/propolis-server-debug.tar.gz
752025-09-15T22:24:23.534Z 129 1 -rw-r--r-- 1 root root 65 Sep 15 22:23 /input/phd-build/out/phd-runner.sha256.txt
762025-09-15T22:24:23.534Z 128 3 -rw-r--r-- 1 root root 2402 Sep 15 22:23 /input/phd-build/out/phd-run-with-args.sh
772025-09-15T22:24:23.534Z 256 1 -rw-r--r-- 1 root root 65 Sep 15 22:23 /input/phd-build/out/propolis-server-debug.sha256.txt
782025-09-15T22:24:23.534Z+ rm -rf /work/phd-test
792025-09-15T22:24:23.535Z+ mkdir /work/phd-test
802025-09-15T22:24:23.535Z+ for p in $indir/$indir_suffix
812025-09-15T22:24:23.535Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
822025-09-15T22:24:26.184ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
832025-09-15T22:24:26.186Zx phd-runner, 393015496 bytes, 767609 tape blocks
842025-09-15T22:24:26.186Zx artifacts.toml, 548 bytes, 2 tape blocks
852025-09-15T22:24:26.210Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
862025-09-15T22:24:28.403Z+ for f in $(tar tf "$p")
872025-09-15T22:24:28.403Z+ chmod +x /work/phd-test/phd-runner
882025-09-15T22:24:28.428Z+ for f in $(tar tf "$p")
892025-09-15T22:24:28.428Z+ chmod +x /work/phd-test/artifacts.toml
902025-09-15T22:24:28.428Z+ for p in $indir/$indir_suffix
912025-09-15T22:24:28.428Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
922025-09-15T22:24:32.012ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
932025-09-15T22:24:32.012Zx propolis-server, 585239968 bytes, 1143047 tape blocks
942025-09-15T22:24:32.037Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
952025-09-15T22:24:35.230Z+ for f in $(tar tf "$p")
962025-09-15T22:24:35.230Z+ chmod +x /work/phd-test/propolis-server
972025-09-15T22:24:35.255Z+ ls /work/phd-test
982025-09-15T22:24:35.255Zartifacts.toml
992025-09-15T22:24:35.255Zphd-runner
1002025-09-15T22:24:35.255Zpropolis-server
1012025-09-15T22:24:35.255Z+ banner Setup
1022025-09-15T22:24:35.255Z #####
1032025-09-15T22:24:35.255Z# # ###### ##### # # #####
1042025-09-15T22:24:35.255Z# # # # # # #
1052025-09-15T22:24:35.255Z ##### ##### # # # # #
1062025-09-15T22:24:35.255Z # # # # # #####
1072025-09-15T22:24:35.255Z# # # # # # #
1082025-09-15T22:24:35.255Z ##### ###### # #### #
1092025-09-15T22:24:35.255Z
1102025-09-15T22:24:35.255Z+ tmpdir=/tmp/propolis-phd
1112025-09-15T22:24:35.255Z+ '[' '!' -d /tmp/propolis-phd ']'
1122025-09-15T22:24:35.255Z+ mkdir /tmp/propolis-phd
1132025-09-15T22:24:35.255Z+ pfexec /usr/lib/rsrvrctl -s 4096
1142025-09-15T22:24:35.851Z+ banner Tests
1152025-09-15T22:24:35.876Z#######
1162025-09-15T22:24:35.876Z # ###### #### ##### ####
1172025-09-15T22:24:35.876Z # # # # #
1182025-09-15T22:24:35.876Z # ##### #### # ####
1192025-09-15T22:24:35.876Z # # # # #
1202025-09-15T22:24:35.876Z # # # # # # #
1212025-09-15T22:24:35.876Z # ###### #### # ####
1222025-09-15T22:24:35.876Z
1232025-09-15T22:24:35.876Z+ runner=/work/phd-test/phd-runner
1242025-09-15T22:24:35.876Z+ artifacts=/work/phd-test/artifacts.toml
1252025-09-15T22:24:35.876Z+ propolis=/work/phd-test/propolis-server
1262025-09-15T22:24:35.876Z+ ls /work/phd-test/phd-runner
1272025-09-15T22:24:35.877Z/work/phd-test/phd-runner
1282025-09-15T22:24:35.877Z+ ls /work/phd-test/artifacts.toml
1292025-09-15T22:24:35.877Z/work/phd-test/artifacts.toml
1302025-09-15T22:24:35.877Z+ ls /work/phd-test/propolis-server
1312025-09-15T22:24:35.877Z/work/phd-test/propolis-server
1322025-09-15T22:24:35.877Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1332025-09-15T22:24:35.877Z+ set +e
1342025-09-15T22:24:35.877Z+ RUST_BACKTRACE=1
1352025-09-15T22:24:35.877Z+ RUST_LOG=info,phd=debug
1362025-09-15T22:24:35.877Z+ 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-09-15T22:24:35.877Z+ tee /tmp/phd-runner.log
1382025-09-15T22:24:35.903Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.113106191Z","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-09-15T22:24:35.904Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.115804171Z","target":"phd_framework::artifacts::store","line":221,"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: 453, tv_nsec: 705589461 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1402025-09-15T22:24:35.904Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.115853832Z","target":"phd_framework::artifacts::store","line":229,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1412025-09-15T22:24:35.904Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.115969822Z","target":"phd_framework::artifacts::store","line":313,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"779775d5130ff7a4836f52f48b7e64d1479ee104"}
1422025-09-15T22:24:35.904Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.116126783Z","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/779775d5130ff7a4836f52f48b7e64d1479ee104/crucible-nightly.sha256.txt","timeout":"600s"}
1432025-09-15T22:24:36.098Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.316485745Z","target":"phd_framework::artifacts::store","line":250,"file":"phd-tests/framework/src/artifacts/store.rs"}
1442025-09-15T22:24:36.626Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.844262576Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/4f4a671817ca190b0f71ae314cef3fb96f85edc8/propolis-server.sha256.txt"}
1452025-09-15T22:24:36.764Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.983161128Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1462025-09-15T22:24:36.789Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.983317948Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1472025-09-15T22:24:36.789Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.983515729Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1482025-09-15T22:24:36.789Z{"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-09-15T22:24:35.98362371Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1492025-09-15T22:24:36.789Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.98369429Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1502025-09-15T22:24:36.789Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.98375825Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1512025-09-15T22:24:36.789Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.984069341Z","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"}
1522025-09-15T22:24:36.792Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.984509813Z","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::migration_from_base_and_back"}
1532025-09-15T22:24:36.792Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:35.984713264Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/907a5fd1763ce5ddd74001261e5b52cd200a25f9/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1542025-09-15T22:24:38.067Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:24:37.28500899Z","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::migration_from_base_and_back"}
1552025-09-15T22:24:38.097Z{"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-09-15T22:24:37.315930351Z","target":"phd_framework::artifacts::store","line":621,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1562025-09-15T22:25:05.662Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.880107402Z","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"}
1572025-09-15T22:25:05.663Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.880249162Z","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"}
1582025-09-15T22:25:05.688Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.88732665Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2.00M 1.80T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1592025-09-15T22:25:05.688Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.887552301Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-dc04da67-e5d3-4ead-9b61-2964468c1ebb\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1602025-09-15T22:25:05.717Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.934944476Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-dc04da67-e5d3-4ead-9b61-2964468c1ebb\", \"phd-artifacts/phd-clone-ed2ce312-23eb-4814-a48b-dc34701807f8\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1612025-09-15T22:25:05.741Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.947118503Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-ed2ce312-23eb-4814-a48b-dc34701807f8\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1622025-09-15T22:25:05.741Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.95402653Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-ed2ce312-23eb-4814-a48b-dc34701807f8 0B 1.80T 48.9M /phd-artifacts/phd-clone-ed2ce312-23eb-4814-a48b-dc34701807f8\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1632025-09-15T22:25:05.741Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.954693983Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1642025-09-15T22:25:05.741Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.954768343Z","target":"phd_framework::test_vm","line":316,"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"}
1652025-09-15T22:25:05.741Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.954816663Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/de36bbdf1de9e323931db0a6921a211978af241507881e0bf34e9257121bcbcd/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1662025-09-15T22:25:05.741Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:04.954864543Z","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/4f4a671817ca190b0f71ae314cef3fb96f85edc8/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1672025-09-15T22:25:32.964Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:32.181528366Z","target":"phd_framework::artifacts::store","line":162,"file":"phd-tests/framework/src/artifacts/store.rs","untar_path":"propolis-server","extracted_path":"/phd-artifacts/de36bbdf1de9e323931db0a6921a211978af241507881e0bf34e9257121bcbcd/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1682025-09-15T22:25:32.964Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:32.181597266Z","target":"phd_framework::artifacts::store","line":521,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1692025-09-15T22:25:47.510Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.713834021Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/de36bbdf1de9e323931db0a6921a211978af241507881e0bf34e9257121bcbcd/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1702025-09-15T22:25:47.511Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.713976761Z","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"}
1712025-09-15T22:25:47.561Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 868","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.777154668Z","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"}
1722025-09-15T22:25:47.593Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.808850432Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1732025-09-15T22:25:47.626Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.811638612Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":41856}
1742025-09-15T22:25:47.667Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.879391127Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1752025-09-15T22:25:47.697Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.879986599Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 5a5490c7-25df-4a07-aaae-142223b67042, metadata: InstanceMetadata { project_id: 274c64fd-0ede-4607-a77d-6f79b085ac34, silo_id: 76685f4d-eca5-4c61-912c-fecde9f6e559, sled_id: 68733f6d-28b1-4a68-8894-9a0147441e0f, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"68733f6d-28b1-4a68-8894-9a0147441e0f\" }, name: \"phd-vm-5a5490c7-25df-4a07-aaae-142223b67042\" }, state: Creating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1762025-09-15T22:25:47.698Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.88008721Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1772025-09-15T22:25:47.698Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.88012624Z","target":"phd_framework::test_vm","line":571,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1782025-09-15T22:25:47.698Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.880865723Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":0}
1792025-09-15T22:25:47.698Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.880927533Z","target":"phd_framework::test_vm","line":883,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1802025-09-15T22:25:47.698Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.880995843Z","target":"phd_framework::test_vm","line":832,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","timeout_duration":"300s","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1812025-09-15T22:25:47.698Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.881048154Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1822025-09-15T22:25:47.699Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:46.881082794Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1832025-09-15T22:25:47.699Z{"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-09-15T22:25:46.881114224Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1842025-09-15T22:25:52.139Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.3550196Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":4473}
1852025-09-15T22:25:52.139Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.35509372Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1862025-09-15T22:25:52.139Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.355399991Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1872025-09-15T22:25:52.139Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.355446091Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1882025-09-15T22:25:52.164Z{"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-09-15T22:25:51.355476801Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1892025-09-15T22:25:52.164Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.373603422Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":18}
1902025-09-15T22:25:52.164Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.373719333Z","target":"phd_framework::test_vm","line":840,"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"}
1912025-09-15T22:25:52.164Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.373891263Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1922025-09-15T22:25:52.164Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.373945453Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1932025-09-15T22:25:52.165Z{"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-09-15T22:25:51.373979383Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1942025-09-15T22:25:52.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.406129879Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":32}
1952025-09-15T22:25:52.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.406233809Z","target":"phd_framework::test_vm","line":880,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1962025-09-15T22:25:52.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.40629655Z","target":"phd_framework::test_vm","line":883,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4525}
1972025-09-15T22:25:52.214Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.406754171Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1982025-09-15T22:25:52.215Z{"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-09-15T22:25:51.406830512Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
1992025-09-15T22:25:52.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.417870355Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":11}
2002025-09-15T22:25:52.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.418128836Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2012025-09-15T22:25:52.215Z{"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-09-15T22:25:51.418206726Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2022025-09-15T22:25:52.240Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.451198925Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":33}
2032025-09-15T22:25:52.240Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.451367336Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2042025-09-15T22:25:52.240Z{"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-09-15T22:25:51.451414406Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2052025-09-15T22:25:52.266Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.461904707Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":10}
2062025-09-15T22:25:52.266Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.462034987Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2072025-09-15T22:25:52.266Z{"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-09-15T22:25:51.462083507Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2082025-09-15T22:25:52.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.484873587Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":22}
2092025-09-15T22:25:52.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.485157288Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2102025-09-15T22:25:52.291Z{"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-09-15T22:25:51.485233428Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2112025-09-15T22:25:52.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.496758523Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":11}
2122025-09-15T22:25:52.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.496893323Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2132025-09-15T22:25:52.291Z{"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-09-15T22:25:51.496939314Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2142025-09-15T22:25:52.316Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.528966148Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":32}
2152025-09-15T22:25:52.316Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.529196349Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2162025-09-15T22:25:52.316Z{"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-09-15T22:25:51.52927181Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2172025-09-15T22:25:52.341Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.540698684Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":11}
2182025-09-15T22:25:52.341Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.540912135Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2192025-09-15T22:25:52.341Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.540986135Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2202025-09-15T22:25:52.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.563730034Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":22}
2212025-09-15T22:25:52.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.563970895Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2222025-09-15T22:25:52.367Z{"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-09-15T22:25:51.564047665Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2232025-09-15T22:25:52.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.574454676Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":10}
2242025-09-15T22:25:52.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.574673337Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2252025-09-15T22:25:52.367Z{"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-09-15T22:25:51.574734407Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2262025-09-15T22:25:52.392Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.596487882Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":21}
2272025-09-15T22:25:52.392Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.596725783Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2282025-09-15T22:25:52.392Z{"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-09-15T22:25:51.596763553Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2292025-09-15T22:25:52.392Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.607339925Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":10}
2302025-09-15T22:25:52.392Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.607551875Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2312025-09-15T22:25:52.392Z{"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-09-15T22:25:51.607627226Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2322025-09-15T22:25:52.417Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.629434851Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":21}
2332025-09-15T22:25:52.417Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.629623841Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2342025-09-15T22:25:52.417Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.629726582Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2352025-09-15T22:25:52.417Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.629762352Z","target":"phd_framework::test_vm","line":316,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2362025-09-15T22:25:52.417Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.629861413Z","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::migration_from_base_and_back"}
2372025-09-15T22:25:52.417Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.629906643Z","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::migration_from_base_and_back"}
2382025-09-15T22:25:52.417Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.629943903Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2392025-09-15T22:25:52.419Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.629975943Z","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"}
2402025-09-15T22:25:52.443Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 869","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.64974969Z","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"}
2412025-09-15T22:25:52.467Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.680605791Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":50}
2422025-09-15T22:25:52.468Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.680702811Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","target":"migration_from_base_and_back_lifecycle_0","source_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2432025-09-15T22:25:52.468Z{"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-09-15T22:25:51.680760501Z","target":"phd_framework::test_vm","line":633,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"2055114f-291b-4817-9fa1-eb9aa9999d26","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","target":"migration_from_base_and_back_lifecycle_0","source_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2442025-09-15T22:25:52.468Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.680807232Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","source":"migration_from_base_and_back","target_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","source_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2452025-09-15T22:25:52.535Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.751499757Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 8a418aac-c77b-415c-8d1e-5ee2f836ff1a, metadata: InstanceMetadata { project_id: 274c64fd-0ede-4607-a77d-6f79b085ac34, silo_id: 76685f4d-eca5-4c61-912c-fecde9f6e559, sled_id: cb78f787-c289-47f7-846c-c0d161418349, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"cb78f787-c289-47f7-846c-c0d161418349\" }, name: \"phd-vm-8a418aac-c77b-415c-8d1e-5ee2f836ff1a\" }, state: Migrating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","source":"migration_from_base_and_back","target_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","source_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2462025-09-15T22:25:52.559Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:51.751705328Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","target":"migration_from_base_and_back_lifecycle_0","migration_id":"2055114f-291b-4817-9fa1-eb9aa9999d26","source_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2472025-09-15T22:25:54.792Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.004504153Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
2482025-09-15T22:25:55.554Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.770217182Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","target":"migration_from_base_and_back_lifecycle_0","source_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2492025-09-15T22:25:55.554Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.770279023Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","target":"migration_from_base_and_back_lifecycle_0","migration_id":"2055114f-291b-4817-9fa1-eb9aa9999d26","source_id":"5a5490c7-25df-4a07-aaae-142223b67042","elapsed_milliseconds":3018}
2502025-09-15T22:25:55.579Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.771879249Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2512025-09-15T22:25:55.579Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.77215057Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2522025-09-15T22:25:55.579Z{"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-09-15T22:25:54.77219211Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2532025-09-15T22:25:55.579Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.773438335Z","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::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2542025-09-15T22:25:55.632Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.84901229Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":76}
2552025-09-15T22:25:55.657Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.849256391Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm":"migration_from_base_and_back","elapsed_milliseconds":8040}
2562025-09-15T22:25:55.657Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.849473292Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":77}
2572025-09-15T22:25:55.657Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.849606563Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2582025-09-15T22:25:55.657Z{"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-09-15T22:25:54.849648953Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2592025-09-15T22:25:55.686Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.882440151Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":32}
2602025-09-15T22:25:55.686Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.882540331Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__BASE_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2612025-09-15T22:25:55.686Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.882639921Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2622025-09-15T22:25:55.686Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.882716512Z","target":"phd_framework::test_vm","line":316,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2632025-09-15T22:25:55.686Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.882806462Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/de36bbdf1de9e323931db0a6921a211978af241507881e0bf34e9257121bcbcd/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2642025-09-15T22:25:55.686Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.882848542Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/de36bbdf1de9e323931db0a6921a211978af241507881e0bf34e9257121bcbcd/propolis-server\"","server_addr":"127.0.0.1:9004","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2652025-09-15T22:25:55.686Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.882884662Z","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"}
2662025-09-15T22:25:55.686Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 871","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.901782246Z","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"}
2672025-09-15T22:25:55.717Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.932953038Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":50}
2682025-09-15T22:25:55.717Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.933021218Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"87d73480-5435-45ec-ac65-144f80b3aca9","target":"migration_from_base_and_back_lifecycle_1","source_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2692025-09-15T22:25:55.717Z{"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-09-15T22:25:54.933072158Z","target":"phd_framework::test_vm","line":633,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"a2bbca09-3f56-41a4-9b48-7a72b422c601","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"87d73480-5435-45ec-ac65-144f80b3aca9","target":"migration_from_base_and_back_lifecycle_1","source_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2702025-09-15T22:25:55.717Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.933123839Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9","source":"migration_from_base_and_back_lifecycle_0","target_id":"87d73480-5435-45ec-ac65-144f80b3aca9","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","source_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2712025-09-15T22:25:55.778Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.995317401Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 87d73480-5435-45ec-ac65-144f80b3aca9, metadata: InstanceMetadata { project_id: 274c64fd-0ede-4607-a77d-6f79b085ac34, silo_id: 76685f4d-eca5-4c61-912c-fecde9f6e559, sled_id: 8a2747c4-3751-4272-b8e8-53a12bd75c37, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"8a2747c4-3751-4272-b8e8-53a12bd75c37\" }, name: \"phd-vm-87d73480-5435-45ec-ac65-144f80b3aca9\" }, state: Migrating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9","source":"migration_from_base_and_back_lifecycle_0","target_id":"87d73480-5435-45ec-ac65-144f80b3aca9","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","source_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2722025-09-15T22:25:55.803Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:54.995409812Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"87d73480-5435-45ec-ac65-144f80b3aca9","target":"migration_from_base_and_back_lifecycle_1","migration_id":"a2bbca09-3f56-41a4-9b48-7a72b422c601","source_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2732025-09-15T22:25:58.046Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:57.262515312Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7894}}"}
2742025-09-15T22:25:58.996Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.212865042Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"87d73480-5435-45ec-ac65-144f80b3aca9","target":"migration_from_base_and_back_lifecycle_1","source_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2752025-09-15T22:25:58.996Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.212928923Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"87d73480-5435-45ec-ac65-144f80b3aca9","target":"migration_from_base_and_back_lifecycle_1","migration_id":"a2bbca09-3f56-41a4-9b48-7a72b422c601","source_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","elapsed_milliseconds":3217}
2762025-09-15T22:25:59.038Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.21484297Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2772025-09-15T22:25:59.038Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.215078961Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
2782025-09-15T22:25:59.038Z{"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-09-15T22:25:58.215124261Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
2792025-09-15T22:25:59.038Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.215934584Z","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::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
2802025-09-15T22:25:59.078Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.290871257Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":75}
2812025-09-15T22:25:59.078Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.291054998Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":6610,"source_id":"5a5490c7-25df-4a07-aaae-142223b67042","vm_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","source":"migration_from_base_and_back","target_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","vm":"migration_from_base_and_back_lifecycle_0"}
2822025-09-15T22:25:59.078Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.291092998Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":6610,"source_id":"5a5490c7-25df-4a07-aaae-142223b67042"}
2832025-09-15T22:25:59.078Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.291301759Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":76}
2842025-09-15T22:25:59.078Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.291432599Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
2852025-09-15T22:25:59.078Z{"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-09-15T22:25:58.291476039Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
2862025-09-15T22:25:59.118Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.324604989Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":33}
2872025-09-15T22:25:59.118Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.324730269Z","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"}
2882025-09-15T22:25:59.118Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.32484869Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2892025-09-15T22:25:59.118Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.32489339Z","target":"phd_framework::test_vm","line":316,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2902025-09-15T22:25:59.118Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.32495116Z","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"}
2912025-09-15T22:25:59.118Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.3249954Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9006","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2922025-09-15T22:25:59.118Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.32504407Z","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_2.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2932025-09-15T22:25:59.154Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 873","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.3455889Z","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"}
2942025-09-15T22:25:59.189Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.377221454Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":52}
2952025-09-15T22:25:59.189Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.377288254Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","target":"migration_from_base_and_back_lifecycle_2","source_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
2962025-09-15T22:25:59.189Z{"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-09-15T22:25:58.377334855Z","target":"phd_framework::test_vm","line":633,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"3cb912f8-964f-4f8d-a53e-372b4bd7c778","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","target":"migration_from_base_and_back_lifecycle_2","source_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
2972025-09-15T22:25:59.189Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.377379705Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","source":"migration_from_base_and_back_lifecycle_1","target_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","source_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
2982025-09-15T22:25:59.251Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.438575884Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 6df5c1ee-c945-45f3-9b20-01420885ea78, metadata: InstanceMetadata { project_id: 274c64fd-0ede-4607-a77d-6f79b085ac34, silo_id: 76685f4d-eca5-4c61-912c-fecde9f6e559, sled_id: 9cdc8280-db0d-4ffe-b793-68888a7b0dcb, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"9cdc8280-db0d-4ffe-b793-68888a7b0dcb\" }, name: \"phd-vm-6df5c1ee-c945-45f3-9b20-01420885ea78\" }, state: Migrating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","source":"migration_from_base_and_back_lifecycle_1","target_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","source_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
2992025-09-15T22:25:59.252Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:25:58.438667554Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","target":"migration_from_base_and_back_lifecycle_2","migration_id":"3cb912f8-964f-4f8d-a53e-372b4bd7c778","source_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
3002025-09-15T22:26:01.487Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:00.700125973Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7941}}"}
3012025-09-15T22:26:01.524Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:00.739491777Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","target":"migration_from_base_and_back_lifecycle_2","source_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
3022025-09-15T22:26:01.524Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:00.739576447Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","target":"migration_from_base_and_back_lifecycle_2","migration_id":"3cb912f8-964f-4f8d-a53e-372b4bd7c778","source_id":"87d73480-5435-45ec-ac65-144f80b3aca9","elapsed_milliseconds":2300}
3032025-09-15T22:26:01.553Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:00.741777216Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
3042025-09-15T22:26:01.553Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:00.742042127Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3052025-09-15T22:26:01.554Z{"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-09-15T22:26:00.742100347Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3062025-09-15T22:26:01.554Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:00.742716849Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
3072025-09-15T22:26:01.604Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:00.819175258Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":77}
3082025-09-15T22:26:01.629Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:00.819299978Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":5886,"source_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a","vm_id":"87d73480-5435-45ec-ac65-144f80b3aca9","source":"migration_from_base_and_back_lifecycle_0","target_id":"87d73480-5435-45ec-ac65-144f80b3aca9","vm":"migration_from_base_and_back_lifecycle_1"}
3092025-09-15T22:26:01.630Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:00.819335309Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"87d73480-5435-45ec-ac65-144f80b3aca9","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":5886,"source_id":"8a418aac-c77b-415c-8d1e-5ee2f836ff1a"}
3102025-09-15T22:26:02.559Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:01.77526906Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":1033}
3112025-09-15T22:26:02.584Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:01.775500601Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3122025-09-15T22:26:02.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-09-15T22:26:01.775575762Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3132025-09-15T22:26:02.609Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:01.80848573Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":32}
3142025-09-15T22:26:02.609Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:01.808607571Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3152025-09-15T22:26:02.609Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:01.808849161Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3162025-09-15T22:26:02.609Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:01.808996962Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":14929}
3172025-09-15T22:26:02.609Z{"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-09-15T22:26:01.809008192Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3182025-09-15T22:26:02.609Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:01.809126322Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3192025-09-15T22:26:02.609Z{"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-09-15T22:26:01.810039296Z","target":"phd_framework::test_vm","line":1171,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3202025-09-15T22:26:03.305Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.521160502Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3212025-09-15T22:26:03.374Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.588853137Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3222025-09-15T22:26:03.374Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.588929667Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-ed2ce312-23eb-4814-a48b-dc34701807f8\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3232025-09-15T22:26:03.400Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.607908481Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3242025-09-15T22:26:03.400Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.607946141Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-dc04da67-e5d3-4ead-9b61-2964468c1ebb\"]","verb":"destroy","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78"}
3252025-09-15T22:26:03.430Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623303761Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":814}
3262025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623407421Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":814}
3272025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623445242Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3282025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623434952Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":4246,"source_id":"87d73480-5435-45ec-ac65-144f80b3aca9","vm_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","source":"migration_from_base_and_back_lifecycle_1","target_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","vm":"migration_from_base_and_back_lifecycle_2"}
3292025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623469332Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3302025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623468352Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"6df5c1ee-c945-45f3-9b20-01420885ea78","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":4246,"source_id":"87d73480-5435-45ec-ac65-144f80b3aca9"}
3312025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623490992Z","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":86639}
3322025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623493182Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3332025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623562482Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
3342025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623630562Z","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"}
3352025-09-15T22:26:03.431Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623665993Z","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"}
3362025-09-15T22:26:03.432Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623703083Z","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"}
3372025-09-15T22:26:03.433Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.623743413Z","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"}
3382025-09-15T22:26:03.433Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.631011431Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 754M 1.80T 753M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
3392025-09-15T22:26:03.433Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.631072322Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-da4a3d75-1fa4-4e4f-a748-fb2a2ea46b15\"]","path":"phd_tests::migrate::from_base::serial_history"}
3402025-09-15T22:26:03.433Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.641863744Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-da4a3d75-1fa4-4e4f-a748-fb2a2ea46b15\", \"phd-artifacts/phd-clone-8141230c-6284-40e3-a48e-5469d3760573\"]","path":"phd_tests::migrate::from_base::serial_history"}
3412025-09-15T22:26:03.465Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.655413226Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-8141230c-6284-40e3-a48e-5469d3760573\"]","verb":"list","path":"phd_tests::migrate::from_base::serial_history"}
3422025-09-15T22:26:03.465Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.662156803Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-8141230c-6284-40e3-a48e-5469d3760573 0B 1.80T 753M /phd-artifacts/phd-clone-8141230c-6284-40e3-a48e-5469d3760573\n","path":"phd_tests::migrate::from_base::serial_history"}
3432025-09-15T22:26:03.467Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.662630535Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3442025-09-15T22:26:03.469Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.662692575Z","target":"phd_framework::test_vm","line":316,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
3452025-09-15T22:26:03.469Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.662752895Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/de36bbdf1de9e323931db0a6921a211978af241507881e0bf34e9257121bcbcd/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
3462025-09-15T22:26:03.469Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.662806535Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/de36bbdf1de9e323931db0a6921a211978af241507881e0bf34e9257121bcbcd/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
3472025-09-15T22:26:03.469Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.662847615Z","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"}
3482025-09-15T22:26:03.518Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 882","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.683067794Z","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"}
3492025-09-15T22:26:03.570Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.714819838Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":52}
3502025-09-15T22:26:03.571Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.714920029Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3512025-09-15T22:26:03.607Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.778712498Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3522025-09-15T22:26:03.607Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.779437351Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 0e8312ad-f732-4aba-84f4-48869ebad375, metadata: InstanceMetadata { project_id: a488f002-b579-4e98-b83a-a5a5c6aac909, silo_id: 9a18be74-67ad-475b-bc8d-5a1a99f5cb53, sled_id: 72a4c0a1-26f7-43ae-afa3-fbcd27ae83cf, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"72a4c0a1-26f7-43ae-afa3-fbcd27ae83cf\" }, name: \"phd-vm-0e8312ad-f732-4aba-84f4-48869ebad375\" }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3532025-09-15T22:26:03.607Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.779533601Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3542025-09-15T22:26:03.607Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.779577131Z","target":"phd_framework::test_vm","line":571,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3552025-09-15T22:26:03.607Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.780219164Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3562025-09-15T22:26:03.608Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.780268744Z","target":"phd_framework::test_vm","line":883,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3572025-09-15T22:26:03.608Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.780306634Z","target":"phd_framework::test_vm","line":832,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375","path":"phd_tests::migrate::from_base::serial_history"}
3582025-09-15T22:26:03.608Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.780335744Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
3592025-09-15T22:26:03.608Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:02.780363874Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3602025-09-15T22:26:03.608Z{"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-09-15T22:26:02.780397474Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3612025-09-15T22:26:07.986Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.201931126Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4421,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3622025-09-15T22:26:07.986Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.202000816Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
3632025-09-15T22:26:08.012Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.202173427Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3642025-09-15T22:26:08.012Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.202217457Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3652025-09-15T22:26:08.012Z{"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-09-15T22:26:07.202246747Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3662025-09-15T22:26:08.012Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.221822853Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":19,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3672025-09-15T22:26:08.012Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.221924844Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3682025-09-15T22:26:08.012Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.222100845Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3692025-09-15T22:26:08.012Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.222153805Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3702025-09-15T22:26:08.012Z{"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-09-15T22:26:07.222185925Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3712025-09-15T22:26:08.041Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.255535775Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3722025-09-15T22:26:08.066Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.255633885Z","target":"phd_framework::test_vm","line":880,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3732025-09-15T22:26:08.066Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.255695836Z","target":"phd_framework::test_vm","line":883,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4475}
3742025-09-15T22:26:08.066Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.255901977Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3752025-09-15T22:26:08.066Z{"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-09-15T22:26:07.255950267Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3762025-09-15T22:26:08.066Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.266568648Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3772025-09-15T22:26:08.066Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.266771969Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3782025-09-15T22:26:08.066Z{"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-09-15T22:26:07.266840599Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3792025-09-15T22:26:08.091Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.300092659Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3802025-09-15T22:26:08.091Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.30031543Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3812025-09-15T22:26:08.092Z{"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-09-15T22:26:07.30039035Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3822025-09-15T22:26:08.117Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.310798581Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3832025-09-15T22:26:08.117Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.311025602Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3842025-09-15T22:26:08.117Z{"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-09-15T22:26:07.311114302Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3852025-09-15T22:26:08.117Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.332899717Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":21,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
3862025-09-15T22:26:08.142Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.337363335Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3872025-09-15T22:26:08.142Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.337426975Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3882025-09-15T22:26:08.142Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.337462805Z","target":"phd_framework::test_vm","line":316,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3892025-09-15T22:26:08.142Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.337508265Z","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"}
3902025-09-15T22:26:08.142Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.337548985Z","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"}
3912025-09-15T22:26:08.142Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.337581425Z","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"}
3922025-09-15T22:26:08.142Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 883","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.357147242Z","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"}
3932025-09-15T22:26:08.172Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.388601964Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":51}
3942025-09-15T22:26:08.172Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.388670095Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0e8312ad-f732-4aba-84f4-48869ebad375","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","target_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
3952025-09-15T22:26:08.173Z{"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-09-15T22:26:07.388716885Z","target":"phd_framework::test_vm","line":633,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"c540e195-2e56-4378-bcb9-1271e9bc071e","source_id":"0e8312ad-f732-4aba-84f4-48869ebad375","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","target_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
3962025-09-15T22:26:08.199Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.388762245Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390","source_id":"0e8312ad-f732-4aba-84f4-48869ebad375","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","target_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
3972025-09-15T22:26:08.234Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.450173105Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: dc8a8d8f-a95d-4080-a701-47d008fb2390, metadata: InstanceMetadata { project_id: a488f002-b579-4e98-b83a-a5a5c6aac909, silo_id: 9a18be74-67ad-475b-bc8d-5a1a99f5cb53, sled_id: 03767554-9af8-487d-aa49-913d91ed2521, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"03767554-9af8-487d-aa49-913d91ed2521\" }, name: \"phd-vm-dc8a8d8f-a95d-4080-a701-47d008fb2390\" }, state: Migrating }","vm":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390","source_id":"0e8312ad-f732-4aba-84f4-48869ebad375","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","target_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
3982025-09-15T22:26:08.234Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:07.450264035Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0e8312ad-f732-4aba-84f4-48869ebad375","migration_id":"c540e195-2e56-4378-bcb9-1271e9bc071e","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","target_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
3992025-09-15T22:26:10.501Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:09.717428296Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7756}}"}
4002025-09-15T22:26:12.297Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.513082567Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"0e8312ad-f732-4aba-84f4-48869ebad375","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","target_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4012025-09-15T22:26:12.297Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.513169477Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4062,"source_id":"0e8312ad-f732-4aba-84f4-48869ebad375","migration_id":"c540e195-2e56-4378-bcb9-1271e9bc071e","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","target_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4022025-09-15T22:26:12.323Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.514818864Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
4032025-09-15T22:26:12.323Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.515923868Z","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":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
4042025-09-15T22:26:12.375Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.585080468Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":70,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
4052025-09-15T22:26:12.400Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.585207828Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":8870,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"0e8312ad-f732-4aba-84f4-48869ebad375"}
4062025-09-15T22:26:12.400Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.587544377Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4072025-09-15T22:26:12.400Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.587715168Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
4082025-09-15T22:26:12.400Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.587776838Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
4092025-09-15T22:26:12.400Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.587824718Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
4102025-09-15T22:26:12.400Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.587828369Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8809}
4112025-09-15T22:26:12.400Z{"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-09-15T22:26:11.588943443Z","target":"phd_framework::test_vm","line":1171,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4122025-09-15T22:26:12.728Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:11.94427773Z","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":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4132025-09-15T22:26:12.801Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.017425785Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4142025-09-15T22:26:12.801Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.017503246Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-8141230c-6284-40e3-a48e-5469d3760573\"]","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4152025-09-15T22:26:12.827Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.037509244Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4162025-09-15T22:26:12.827Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.037546544Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-da4a3d75-1fa4-4e4f-a748-fb2a2ea46b15\"]","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4172025-09-15T22:26:12.851Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.052823553Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":465,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4182025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.052962034Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":465}
4192025-09-15T22:26:12.852Z{"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-09-15T22:26:12.053012884Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
4202025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053020464Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4664,"source_id":"0e8312ad-f732-4aba-84f4-48869ebad375","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","vm":"migration_serial_history_base_lifecycle_0","target_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4212025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053047304Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
4222025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053056134Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4664,"source_id":"0e8312ad-f732-4aba-84f4-48869ebad375","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","target_id":"dc8a8d8f-a95d-4080-a701-47d008fb2390"}
4232025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053078534Z","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":9429}
4242025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053079025Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4252025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053166955Z","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"}
4262025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053240315Z","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::can_migrate_from_base"}
4272025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053276805Z","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"}
4282025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053315966Z","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"}
4292025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.053357346Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4302025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.060627114Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 754M 1.80T 753M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4312025-09-15T22:26:12.852Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.060692404Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-db75e9ff-d374-4570-b631-e5a0fd2da818\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4322025-09-15T22:26:12.877Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.073989066Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-db75e9ff-d374-4570-b631-e5a0fd2da818\", \"phd-artifacts/phd-clone-1732f2c6-b236-48be-88d8-91868a2443e2\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4332025-09-15T22:26:12.877Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.089160835Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-1732f2c6-b236-48be-88d8-91868a2443e2\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4342025-09-15T22:26:12.902Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.09543962Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-1732f2c6-b236-48be-88d8-91868a2443e2 0B 1.80T 753M /phd-artifacts/phd-clone-1732f2c6-b236-48be-88d8-91868a2443e2\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4352025-09-15T22:26:12.902Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.095972622Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4362025-09-15T22:26:12.902Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.096014852Z","target":"phd_framework::test_vm","line":316,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4372025-09-15T22:26:12.902Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.096049062Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/de36bbdf1de9e323931db0a6921a211978af241507881e0bf34e9257121bcbcd/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4382025-09-15T22:26:12.902Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.096085313Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/de36bbdf1de9e323931db0a6921a211978af241507881e0bf34e9257121bcbcd/propolis-server\"","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4392025-09-15T22:26:12.902Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.096125862Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4402025-09-15T22:26:12.902Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 892","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.115514628Z","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"}
4412025-09-15T22:26:12.932Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.147690654Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":51,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4422025-09-15T22:26:12.956Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.147757554Z","target":"phd_framework::test_vm","line":407,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4432025-09-15T22:26:12.993Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.209465445Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
4442025-09-15T22:26:13.018Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.210227018Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 6093a902-e285-45f8-986c-a7d956352c6c, metadata: InstanceMetadata { project_id: a5c71226-6235-45c1-8433-1095fa168776, silo_id: 27bbdeca-0e80-4530-9478-80568cdb6916, sled_id: b2484786-50b9-4bf0-ad5d-3bd2b8f70b76, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"b2484786-50b9-4bf0-ad5d-3bd2b8f70b76\" }, name: \"phd-vm-6093a902-e285-45f8-986c-a7d956352c6c\" }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4452025-09-15T22:26:13.018Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.210337359Z","target":"phd_framework::test_vm","line":566,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4462025-09-15T22:26:13.019Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.210372609Z","target":"phd_framework::test_vm","line":571,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4472025-09-15T22:26:13.019Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.211087682Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4482025-09-15T22:26:13.019Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.211141622Z","target":"phd_framework::test_vm","line":883,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4492025-09-15T22:26:13.019Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.211180312Z","target":"phd_framework::test_vm","line":832,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","timeout_duration":"300s","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4502025-09-15T22:26:13.019Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.211209282Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4512025-09-15T22:26:13.019Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:12.211237732Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4522025-09-15T22:26:13.019Z{"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-09-15T22:26:12.211266582Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4532025-09-15T22:26:17.418Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.633952458Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":4422,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4542025-09-15T22:26:17.418Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.634011059Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4552025-09-15T22:26:17.443Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.63418657Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4562025-09-15T22:26:17.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.634227839Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4572025-09-15T22:26:17.444Z{"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-09-15T22:26:16.63425683Z","target":"phd_framework::test_vm","line":905,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4582025-09-15T22:26:17.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.653263334Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4592025-09-15T22:26:17.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.653386874Z","target":"phd_framework::test_vm","line":840,"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"}
4602025-09-15T22:26:17.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.653707456Z","target":"phd_framework::test_vm","line":840,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4612025-09-15T22:26:17.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.653805346Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4622025-09-15T22:26:17.444Z{"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-09-15T22:26:16.653868436Z","target":"phd_framework::test_vm","line":905,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4632025-09-15T22:26:17.470Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.685881641Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4642025-09-15T22:26:17.470Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.685981872Z","target":"phd_framework::test_vm","line":880,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4652025-09-15T22:26:17.470Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.686053962Z","target":"phd_framework::test_vm","line":883,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4474,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4662025-09-15T22:26:17.495Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.686312643Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4672025-09-15T22:26:17.495Z{"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-09-15T22:26:16.686401103Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4682025-09-15T22:26:17.495Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.696899674Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4692025-09-15T22:26:17.495Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.697121005Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4702025-09-15T22:26:17.495Z{"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-09-15T22:26:16.697196725Z","target":"phd_framework::test_vm","line":905,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4712025-09-15T22:26:17.520Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.730054084Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4722025-09-15T22:26:17.520Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.730285025Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4732025-09-15T22:26:17.520Z{"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-09-15T22:26:16.730358965Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4742025-09-15T22:26:17.546Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.740885916Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4752025-09-15T22:26:17.546Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.741125487Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4762025-09-15T22:26:17.546Z{"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-09-15T22:26:16.741214647Z","target":"phd_framework::test_vm","line":905,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4772025-09-15T22:26:17.573Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.762810092Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":21,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4782025-09-15T22:26:17.573Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.762948182Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4792025-09-15T22:26:17.573Z{"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-09-15T22:26:16.762993402Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4802025-09-15T22:26:17.573Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.773388943Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4812025-09-15T22:26:17.573Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.773599434Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4822025-09-15T22:26:17.573Z{"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-09-15T22:26:16.773674464Z","target":"phd_framework::test_vm","line":905,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4832025-09-15T22:26:17.599Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.796180552Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4842025-09-15T22:26:17.599Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.796406033Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4852025-09-15T22:26:17.599Z{"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-09-15T22:26:16.796481323Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4862025-09-15T22:26:17.599Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.807883908Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4872025-09-15T22:26:17.599Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.808119429Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4882025-09-15T22:26:17.599Z{"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-09-15T22:26:16.808208609Z","target":"phd_framework::test_vm","line":905,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4892025-09-15T22:26:17.625Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.841036417Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4902025-09-15T22:26:17.650Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.841301398Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4912025-09-15T22:26:17.650Z{"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-09-15T22:26:16.841390248Z","target":"phd_framework::test_vm","line":905,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4922025-09-15T22:26:17.650Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.851764899Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4932025-09-15T22:26:17.650Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.85199166Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4942025-09-15T22:26:17.650Z{"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-09-15T22:26:16.8520678Z","target":"phd_framework::test_vm","line":905,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4952025-09-15T22:26:17.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.884854218Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4962025-09-15T22:26:17.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.885124419Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
4972025-09-15T22:26:17.675Z{"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-09-15T22:26:16.88521451Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4982025-09-15T22:26:17.700Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.89558984Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
4992025-09-15T22:26:17.700Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.895809341Z","target":"phd_framework::test_vm","line":898,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
5002025-09-15T22:26:17.700Z{"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-09-15T22:26:16.895884081Z","target":"phd_framework::test_vm","line":905,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
5012025-09-15T22:26:17.724Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.928718579Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
5022025-09-15T22:26:17.724Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.92886763Z","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"}
5032025-09-15T22:26:17.725Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.9289757Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5042025-09-15T22:26:17.725Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.929063021Z","target":"phd_framework::test_vm","line":316,"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_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5052025-09-15T22:26:17.725Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.929162571Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5062025-09-15T22:26:17.725Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.929265271Z","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"}
5072025-09-15T22:26:17.725Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.929364522Z","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"}
5082025-09-15T22:26:17.750Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 893","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.950795146Z","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"}
5092025-09-15T22:26:17.775Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.982104968Z","target":"phd_framework::test_vm","line":298,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":53,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5102025-09-15T22:26:17.775Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.982175038Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6093a902-e285-45f8-986c-a7d956352c6c","target":"migration_from_base_lifecycle_0","target_id":"77464b72-5d73-4b36-b8cf-6921c9f42676","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5112025-09-15T22:26:17.775Z{"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-09-15T22:26:16.982221538Z","target":"phd_framework::test_vm","line":633,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"7d18072c-9c2e-4a06-9ef0-77aa7f74b5b7","timeout_duration":"45s","source_id":"6093a902-e285-45f8-986c-a7d956352c6c","target":"migration_from_base_lifecycle_0","target_id":"77464b72-5d73-4b36-b8cf-6921c9f42676","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5122025-09-15T22:26:17.775Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:16.982267458Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6093a902-e285-45f8-986c-a7d956352c6c","target":"migration_from_base_lifecycle_0","target_id":"77464b72-5d73-4b36-b8cf-6921c9f42676","source":"migration_from_base","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5132025-09-15T22:26:17.829Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:17.044469171Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 77464b72-5d73-4b36-b8cf-6921c9f42676, metadata: InstanceMetadata { project_id: a5c71226-6235-45c1-8433-1095fa168776, silo_id: 27bbdeca-0e80-4530-9478-80568cdb6916, sled_id: e9355ce7-1cf7-4226-a50e-efa245c6271c, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"e9355ce7-1cf7-4226-a50e-efa245c6271c\" }, name: \"phd-vm-77464b72-5d73-4b36-b8cf-6921c9f42676\" }, state: Migrating }","source_id":"6093a902-e285-45f8-986c-a7d956352c6c","target":"migration_from_base_lifecycle_0","target_id":"77464b72-5d73-4b36-b8cf-6921c9f42676","source":"migration_from_base","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5142025-09-15T22:26:17.854Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:17.044563192Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6093a902-e285-45f8-986c-a7d956352c6c","target":"migration_from_base_lifecycle_0","target_id":"77464b72-5d73-4b36-b8cf-6921c9f42676","source":"migration_from_base","migration_id":"7d18072c-9c2e-4a06-9ef0-77aa7f74b5b7","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5152025-09-15T22:26:20.086Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:19.301498293Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
5162025-09-15T22:26:20.732Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:19.947917907Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6093a902-e285-45f8-986c-a7d956352c6c","target":"migration_from_base_lifecycle_0","target_id":"77464b72-5d73-4b36-b8cf-6921c9f42676","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5172025-09-15T22:26:20.732Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:19.947963857Z","target":"phd_framework::test_vm","line":654,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6093a902-e285-45f8-986c-a7d956352c6c","target":"migration_from_base_lifecycle_0","target_id":"77464b72-5d73-4b36-b8cf-6921c9f42676","source":"migration_from_base","migration_id":"7d18072c-9c2e-4a06-9ef0-77aa7f74b5b7","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":2903}
5182025-09-15T22:26:20.758Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:19.949531263Z","target":"phd_framework::test_vm","line":1148,"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":"6093a902-e285-45f8-986c-a7d956352c6c"}
5192025-09-15T22:26:20.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:19.949709803Z","target":"phd_framework::test_vm","line":898,"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":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5202025-09-15T22:26:20.758Z{"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-09-15T22:26:19.949751124Z","target":"phd_framework::test_vm","line":905,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5212025-09-15T22:26:20.758Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:19.950663387Z","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":"6093a902-e285-45f8-986c-a7d956352c6c"}
5222025-09-15T22:26:20.807Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.023026229Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":73,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
5232025-09-15T22:26:20.832Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.02314041Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":7875,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"6093a902-e285-45f8-986c-a7d956352c6c"}
5242025-09-15T22:26:20.832Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.02331339Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":73,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5252025-09-15T22:26:20.832Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.023421481Z","target":"phd_framework::test_vm","line":898,"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":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5262025-09-15T22:26:20.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-09-15T22:26:20.023459571Z","target":"phd_framework::test_vm","line":905,"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":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5272025-09-15T22:26:20.858Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.050444496Z","target":"phd_framework::test_vm","line":898,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":26,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5282025-09-15T22:26:20.858Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.050570157Z","target":"phd_framework::test_vm","line":1148,"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":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5292025-09-15T22:26:20.858Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.050729887Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5302025-09-15T22:26:20.858Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.050832838Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":7841}
5312025-09-15T22:26:20.858Z{"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-09-15T22:26:20.051005098Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
5322025-09-15T22:26:20.858Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.051117299Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5332025-09-15T22:26:20.858Z{"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-09-15T22:26:20.051791901Z","target":"phd_framework::test_vm","line":1171,"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":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5342025-09-15T22:26:21.262Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.477305433Z","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":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5352025-09-15T22:26:21.329Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.544678806Z","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":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5362025-09-15T22:26:21.329Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.544726816Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-1732f2c6-b236-48be-88d8-91868a2443e2\"]","verb":"destroy","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5372025-09-15T22:26:21.354Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.564865685Z","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":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5382025-09-15T22:26:21.354Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.564911225Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-db75e9ff-d374-4570-b631-e5a0fd2da818\"]","verb":"destroy","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5392025-09-15T22:26:21.379Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.57892585Z","target":"phd_framework::test_vm","line":1148,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":528,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5402025-09-15T22:26:21.380Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.57905628Z","target":"phd_framework::test_vm","line":407,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","target_id":"77464b72-5d73-4b36-b8cf-6921c9f42676","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"6093a902-e285-45f8-986c-a7d956352c6c","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":3596,"vm_id":"77464b72-5d73-4b36-b8cf-6921c9f42676"}
5412025-09-15T22:26:21.380Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.57909093Z","target":"phd_framework::test_vm","line":600,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"6093a902-e285-45f8-986c-a7d956352c6c","target":"migration_from_base_lifecycle_0","target_id":"77464b72-5d73-4b36-b8cf-6921c9f42676","source":"migration_from_base","elapsed_milliseconds":3596,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5422025-09-15T22:26:21.381Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.57911454Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":8525,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5432025-09-15T22:26:21.381Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.5791344Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":527}
5442025-09-15T22:26:21.381Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.579239881Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5452025-09-15T22:26:21.381Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.579281221Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5462025-09-15T22:26:21.381Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 104.60s
5472025-09-15T22:26:21.381Z
5482025-09-15T22:26:21.381Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"buskin","pid":863,"time":"2025-09-15T22:26:20.579384021Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5492025-09-15T22:26:21.430Z
5502025-09-15T22:26:21.455Zreal 1:45.496288878
5512025-09-15T22:26:21.455Zuser 36.103536589
5522025-09-15T22:26:21.455Zsys 16.118103222
5532025-09-15T22:26:21.455Ztrap 0.006849451
5542025-09-15T22:26:21.455Ztflt 0.001506593
5552025-09-15T22:26:21.455Zdflt 0.000516571
5562025-09-15T22:26:21.455Zkflt 0.000133876
5572025-09-15T22:26:21.455Zlock 1:41:32.939075828
5582025-09-15T22:26:21.455Zslp 3:58.450564810
5592025-09-15T22:26:21.455Zlat 1.171318647
5602025-09-15T22:26:21.455Zstop 8.428712685
5612025-09-15T22:26:21.455Z+ failcount=0
5622025-09-15T22:26:21.455Z+ set -e
5632025-09-15T22:26:21.455Z+ 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
5642025-09-15T22:26:21.455ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5652025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5662025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log 233K
5672025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5682025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log 233K
5692025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5702025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log 146K
5712025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_and_back.serial.log 7K
5722025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_and_back.stderr.log 0K
5732025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_and_back.stdout.log 140K
5742025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log 0K
5752025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log 146K
5762025-09-15T22:26:21.455Za /tmp/propolis-phd/migration_from_base.serial.log 7K
5772025-09-15T22:26:21.456Za /tmp/propolis-phd/migration_from_base.stderr.log 0K
5782025-09-15T22:26:21.456Za /tmp/propolis-phd/migration_from_base.stdout.log 140K
5792025-09-15T22:26:21.456Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log 0K
5802025-09-15T22:26:21.456Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log 146K
5812025-09-15T22:26:21.456Za /tmp/propolis-phd/migration_serial_history_base.serial.log 7K
5822025-09-15T22:26:21.456Za /tmp/propolis-phd/migration_serial_history_base.stderr.log 0K
5832025-09-15T22:26:21.456Za /tmp/propolis-phd/migration_serial_history_base.stdout.log 139K
5842025-09-15T22:26:21.456Z+ exitcode=0
5852025-09-15T22:26:21.456Z+ '[' 0 -eq 0 ']'
5862025-09-15T22:26:21.456Z+ echo
5872025-09-15T22:26:21.456Z
5882025-09-15T22:26:21.456Z+ echo 'ALL TESTS PASSED'
5892025-09-15T22:26:21.456ZALL TESTS PASSED
5902025-09-15T22:26:21.456Z+ echo
5912025-09-15T22:26:21.456Z
5922025-09-15T22:26:21.456Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5932025-09-15T22:26:21.456Z+ read
5942025-09-15T22:26:21.456Z+ exit 0
5952025-09-15T22:26:21.456Zprocess exited: duration 118128 ms, exit code 0
 
5962025-09-15T22:26:21.508Zfound 2 output files
5972025-09-15T22:26:21.508Zuploading: /tmp/phd-runner.log (176242 bytes)
5982025-09-15T22:26:22.677Zuploaded: /tmp/phd-runner.log
5992025-09-15T22:26:22.677Zuploading: /tmp/phd-tmp-files.tar.gz (104231 bytes)
6002025-09-15T22:26:23.888Zuploaded: /tmp/phd-tmp-files.tar.gz