01K05716P71XMXADQS5275FBBM: 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: 01K0571M2M1A96F458C609CMEC

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-07-14T19:46:33.397Zjob dependencies complete; ready to run (waiting for 9 m 31 s)
22025-07-14T19:59:44.400Zjob assigned to worker 01K05861X757VGF5JCZP65TT6T [factory lab, buskin/15793] (queued for 13 m 11 s)
32025-07-14T19:59:44.690Zhttp://172.20.0.5:9969/ipxe/buskin... ok
42025-07-14T19:59:44.739Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/kernel/amd64/unix... ok
52025-07-14T19:59:44.772Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive... ok
62025-07-14T19:59:44.805Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive.hash... ok
72025-07-14T19:59:44.839Zhttp://172.20.0.5:9969/postboot/buskin... ok
82025-07-14T19:59:44.872ZwcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U
92025-07-14T19:59:44.906Zcpu0: microcode has been updated from version 0xa001133 to 0xa0011d5
102025-07-14T19:59:44.939ZOxide Helios Version helios-2.0.23457 64-bit
112025-07-14T19:59:45.006ZConfiguring devices.
122025-07-14T19:59:45.039Z##################################################
132025-07-14T19:59:45.072Z#### ############# ##
142025-07-14T19:59:45.106Z### ### ############ ##
152025-07-14T19:59:45.139Z## ### # ## ### ## Oxide Computer Company ##
162025-07-14T19:59:45.173Z## ## ## ### # ### ##
172025-07-14T19:59:45.206Z## # ### #### #### This Station Under ##
182025-07-14T19:59:45.240Z### ### #### # ### Computer Control ##
192025-07-14T19:59:45.273Z#### #### ### ## ##
202025-07-14T19:59:45.329Z##################################################
212025-07-14T19:59:45.379ZHostname: buskin
222025-07-14T19:59:45.418ZLoading smf(7) service descriptions:
232025-07-14T19:59:46.090Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
242025-07-14T19:59:46.116Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
252025-07-14T19:59:46.116Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
262025-07-14T19:59:46.151Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
272025-07-14T19:59:46.176Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
282025-07-14T20:00:05.008Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
292025-07-14T20:00:05.008Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
302025-07-14T20:00:05.073Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
312025-07-14T20:00:05.073Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
322025-07-14T20:00:32.615Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
332025-07-14T20:00:32.639Zstarting task 0: "setup"
342025-07-14T20:00:32.639Z++ uname -s
352025-07-14T20:00:32.639Z+ kern=SunOS
362025-07-14T20:00:32.640Z+ build_user=build
372025-07-14T20:00:32.640Z+ build_uid=12345
382025-07-14T20:00:32.640Z+ work_dir=/work
392025-07-14T20:00:32.640Z+ input_dir=/input
402025-07-14T20:00:32.640Z+ [[ 0 == 12345 ]]
412025-07-14T20:00:32.640Z+ case "$kern" in
422025-07-14T20:00:32.640Z+ groupadd -g 12345 build
432025-07-14T20:00:32.640Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
442025-07-14T20:00:34.632Z+ zfs create -o mountpoint=/work rpool/work
452025-07-14T20:00:34.656Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
462025-07-14T20:00:34.656Z+ home_fs=zfs
472025-07-14T20:00:34.656Z+ [[ zfs == autofs ]]
482025-07-14T20:00:34.656Z+ mkdir -p /home/build
492025-07-14T20:00:34.656Z+ chown build:build /home/build /work
502025-07-14T20:00:36.656Z+ chmod 0700 /home/build /work
512025-07-14T20:00:36.691Zprocess exited: duration 4044 ms, exit code 0
 
522025-07-14T20:00:36.743Zstarting task 1: "authentication"
532025-07-14T20:00:36.796Zprocess exited: duration 52 ms, exit code 0
 
542025-07-14T20:00:36.849Zstarting task 2: "build"
552025-07-14T20:00:36.875Z+ indir=/input
562025-07-14T20:00:36.875Z+ indir_suffix='phd-build/out/*.tar.gz'
572025-07-14T20:00:36.875Z+ phddir=/work/phd-test
582025-07-14T20:00:36.875Z+ pfexec zpool create -f phd-artifacts c1t1d0 c2t1d0
592025-07-14T20:00:37.025Z+ artifactdir=/phd-artifacts
602025-07-14T20:00:37.026Z+ banner Inputs
612025-07-14T20:00:37.052Z ###
622025-07-14T20:00:37.052Z # # # ##### # # ##### ####
632025-07-14T20:00:37.052Z # ## # # # # # # #
642025-07-14T20:00:37.052Z # # # # # # # # # ####
652025-07-14T20:00:37.052Z # # # # ##### # # # #
662025-07-14T20:00:37.052Z # # ## # # # # # #
672025-07-14T20:00:37.052Z ### # # # #### # ####
682025-07-14T20:00:37.052Z
692025-07-14T20:00:37.053Z+ find /input -ls
702025-07-14T20:00:37.053Z 34 1 drwxr-xr-x 3 root root 3 Jul 14 19:59 /input
712025-07-14T20:00:37.053Z 2 1 drwxr-xr-x 3 root root 3 Jul 14 19:59 /input/phd-build
722025-07-14T20:00:37.053Z 3 2 drwxr-xr-x 2 root root 7 Jul 14 20:00 /input/phd-build/out
732025-07-14T20:00:37.053Z 5 1 -rw-r--r-- 1 root root 65 Jul 14 19:59 /input/phd-build/out/phd-runner.sha256.txt
742025-07-14T20:00:37.053Z 4 3 -rw-r--r-- 1 root root 2402 Jul 14 19:59 /input/phd-build/out/phd-run-with-args.sh
752025-07-14T20:00:37.053Z 128 1 -rw-r--r-- 1 root root 65 Jul 14 20:00 /input/phd-build/out/propolis-server-debug.sha256.txt
762025-07-14T20:00:37.053Z 6 106254 -rw-r--r-- 1 root root 108735076 Jul 14 20:00 /input/phd-build/out/phd-runner.tar.gz
772025-07-14T20:00:37.053Z 129 149564 -rw-r--r-- 1 root root 153054474 Jul 14 20:00 /input/phd-build/out/propolis-server-debug.tar.gz
782025-07-14T20:00:37.053Z+ rm -rf /work/phd-test
792025-07-14T20:00:37.053Z+ mkdir /work/phd-test
802025-07-14T20:00:37.053Z+ for p in $indir/$indir_suffix
812025-07-14T20:00:37.053Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
822025-07-14T20:00:39.702ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
832025-07-14T20:00:39.703Zx phd-runner, 392885016 bytes, 767354 tape blocks
842025-07-14T20:00:39.703Zx artifacts.toml, 548 bytes, 2 tape blocks
852025-07-14T20:00:39.727Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
862025-07-14T20:00:41.942Z+ for f in $(tar tf "$p")
872025-07-14T20:00:41.942Z+ chmod +x /work/phd-test/phd-runner
882025-07-14T20:00:41.967Z+ for f in $(tar tf "$p")
892025-07-14T20:00:41.967Z+ chmod +x /work/phd-test/artifacts.toml
902025-07-14T20:00:41.967Z+ for p in $indir/$indir_suffix
912025-07-14T20:00:41.967Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
922025-07-14T20:00:45.574ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
932025-07-14T20:00:45.574Zx propolis-server, 586457776 bytes, 1145426 tape blocks
942025-07-14T20:00:45.603Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
952025-07-14T20:00:48.809Z+ for f in $(tar tf "$p")
962025-07-14T20:00:48.809Z+ chmod +x /work/phd-test/propolis-server
972025-07-14T20:00:48.835Z+ ls /work/phd-test
982025-07-14T20:00:48.835Zartifacts.toml
992025-07-14T20:00:48.835Zphd-runner
1002025-07-14T20:00:48.835Zpropolis-server
1012025-07-14T20:00:48.835Z+ banner Setup
1022025-07-14T20:00:48.835Z #####
1032025-07-14T20:00:48.835Z# # ###### ##### # # #####
1042025-07-14T20:00:48.835Z# # # # # # #
1052025-07-14T20:00:48.835Z ##### ##### # # # # #
1062025-07-14T20:00:48.835Z # # # # # #####
1072025-07-14T20:00:48.835Z# # # # # # #
1082025-07-14T20:00:48.835Z ##### ###### # #### #
1092025-07-14T20:00:48.835Z
1102025-07-14T20:00:48.835Z+ tmpdir=/tmp/propolis-phd
1112025-07-14T20:00:48.835Z+ '[' '!' -d /tmp/propolis-phd ']'
1122025-07-14T20:00:48.835Z+ mkdir /tmp/propolis-phd
1132025-07-14T20:00:48.835Z+ pfexec /usr/lib/rsrvrctl -s 4096
1142025-07-14T20:00:49.532Z+ banner Tests
1152025-07-14T20:00:49.557Z#######
1162025-07-14T20:00:49.557Z # ###### #### ##### ####
1172025-07-14T20:00:49.557Z # # # # #
1182025-07-14T20:00:49.557Z # ##### #### # ####
1192025-07-14T20:00:49.557Z # # # # #
1202025-07-14T20:00:49.557Z # # # # # # #
1212025-07-14T20:00:49.557Z # ###### #### # ####
1222025-07-14T20:00:49.557Z
1232025-07-14T20:00:49.557Z+ runner=/work/phd-test/phd-runner
1242025-07-14T20:00:49.557Z+ artifacts=/work/phd-test/artifacts.toml
1252025-07-14T20:00:49.557Z+ propolis=/work/phd-test/propolis-server
1262025-07-14T20:00:49.557Z+ ls /work/phd-test/phd-runner
1272025-07-14T20:00:49.557Z/work/phd-test/phd-runner
1282025-07-14T20:00:49.557Z+ ls /work/phd-test/artifacts.toml
1292025-07-14T20:00:49.557Z/work/phd-test/artifacts.toml
1302025-07-14T20:00:49.557Z+ ls /work/phd-test/propolis-server
1312025-07-14T20:00:49.557Z/work/phd-test/propolis-server
1322025-07-14T20:00:49.557Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1332025-07-14T20:00:49.557Z+ set +e
1342025-07-14T20:00:49.557Z+ RUST_BACKTRACE=1
1352025-07-14T20:00:49.557Z+ RUST_LOG=info,phd=debug
1362025-07-14T20:00:49.558Z+ 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-07-14T20:00:49.558Z+ tee /tmp/phd-runner.log
1382025-07-14T20:00:49.583Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.102914689Z","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-07-14T20:00:49.583Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.105831125Z","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: 326, tv_nsec: 503601573 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1402025-07-14T20:00:49.583Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.105881106Z","target":"phd_framework::artifacts::store","line":229,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1412025-07-14T20:00:49.583Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.105985078Z","target":"phd_framework::artifacts::store","line":313,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"e164393a88e7b62598897dc4f53315f083e25333"}
1422025-07-14T20:00:49.583Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.10611329Z","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/e164393a88e7b62598897dc4f53315f083e25333/crucible-nightly.sha256.txt","timeout":"600s"}
1432025-07-14T20:00:49.756Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.283090977Z","target":"phd_framework::artifacts::store","line":250,"file":"phd-tests/framework/src/artifacts/store.rs"}
1442025-07-14T20:00:50.198Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.724678032Z","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/c03bd1a29c775acfc65de561b8fc436e2459a633/propolis-server.sha256.txt","timeout":"600s"}
1452025-07-14T20:00:50.335Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.86185552Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1462025-07-14T20:00:50.360Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.861983682Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1472025-07-14T20:00:50.360Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.862215587Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1482025-07-14T20:00:50.360Z{"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-07-14T20:00:50.862346359Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1492025-07-14T20:00:50.361Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.86238964Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1502025-07-14T20:00:50.361Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.862435861Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1512025-07-14T20:00:50.361Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.862831009Z","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-07-14T20:00:50.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.863246957Z","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-07-14T20:00:50.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:50.86342371Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/907a5fd1763ce5ddd74001261e5b52cd200a25f9/OVMF_CODE.fd","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1542025-07-14T20:00:50.899Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:00:51.425621173Z","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-07-14T20:00:50.929Z{"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-07-14T20:00:51.45555245Z","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-07-14T20:01:18.104Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.6297018Z","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-07-14T20:01:18.104Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.629810763Z","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-07-14T20:01:18.129Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.637317767Z","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-07-14T20:01:18.129Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.637481851Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-f1c2b1c7-7b4c-4c36-a6d5-5aa9786c4234\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1602025-07-14T20:01:18.158Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.68460734Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-f1c2b1c7-7b4c-4c36-a6d5-5aa9786c4234\", \"phd-artifacts/phd-clone-a0630370-7d2c-452e-8120-6f7abf3095c1\"]","verb":"clone","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1612025-07-14T20:01:18.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.697771215Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-a0630370-7d2c-452e-8120-6f7abf3095c1\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1622025-07-14T20:01:18.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.70425472Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-a0630370-7d2c-452e-8120-6f7abf3095c1 0B 1.80T 48.9M /phd-artifacts/phd-clone-a0630370-7d2c-452e-8120-6f7abf3095c1\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1632025-07-14T20:01:18.184Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.705093506Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1642025-07-14T20:01:18.184Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.705157947Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1652025-07-14T20:01:18.184Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.705198918Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/22dd96ade0a3010628188fb9f4dc21b70dbd1abc21585df8007145a0b2c58b27/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1662025-07-14T20:01:18.184Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:18.705245419Z","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/c03bd1a29c775acfc65de561b8fc436e2459a633/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1672025-07-14T20:01:45.997Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:46.522690166Z","target":"phd_framework::artifacts::store","line":162,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/22dd96ade0a3010628188fb9f4dc21b70dbd1abc21585df8007145a0b2c58b27/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1682025-07-14T20:01:45.998Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:01:46.522779128Z","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-07-14T20:02:00.006Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.531633925Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/22dd96ade0a3010628188fb9f4dc21b70dbd1abc21585df8007145a0b2c58b27/propolis-server\"","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1702025-07-14T20:02:00.006Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.531764248Z","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.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1712025-07-14T20:02:00.062Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 868","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.588644986Z","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-07-14T20:02:00.093Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.619765906Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":41914}
1732025-07-14T20:02:00.118Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.61992603Z","target":"phd_framework::test_vm","line":306,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1742025-07-14T20:02:00.163Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.689637295Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1752025-07-14T20:02:00.190Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.690209706Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: c60b0ad8-acfb-49fc-a6ba-b8300810e6e2, metadata: InstanceMetadata { project_id: ddae4c6b-3de8-4167-92ef-18642586b700, silo_id: 07bdc89b-5681-44e0-946a-167c4c07ddae, sled_id: f9d660a1-d66b-4916-828d-86315fc31157, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"f9d660a1-d66b-4916-828d-86315fc31157\" }, name: \"phd-vm-c60b0ad8-acfb-49fc-a6ba-b8300810e6e2\" }, state: Creating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1762025-07-14T20:02:00.190Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.690284608Z","target":"phd_framework::test_vm","line":306,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":70}
1772025-07-14T20:02:00.190Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.690338159Z","target":"phd_framework::test_vm","line":465,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1782025-07-14T20:02:00.190Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.690372089Z","target":"phd_framework::test_vm","line":470,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1792025-07-14T20:02:00.190Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.691025252Z","target":"phd_framework::test_vm","line":465,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":0}
1802025-07-14T20:02:00.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.691110584Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1812025-07-14T20:02:00.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.691151775Z","target":"phd_framework::test_vm","line":731,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","timeout_duration":"300s","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1822025-07-14T20:02:00.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.691182505Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1832025-07-14T20:02:00.190Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:00.691211656Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1842025-07-14T20:02:00.190Z{"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-07-14T20:02:00.691257787Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1852025-07-14T20:02:04.662Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.187578173Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":4496}
1862025-07-14T20:02:04.662Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.187650565Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1872025-07-14T20:02:04.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.187879559Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1882025-07-14T20:02:04.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.18793307Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1892025-07-14T20:02:04.687Z{"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-07-14T20:02:05.187962061Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1902025-07-14T20:02:04.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.207808544Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":19}
1912025-07-14T20:02:04.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.207904176Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1922025-07-14T20:02:04.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.208173881Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1932025-07-14T20:02:04.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.208228462Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1942025-07-14T20:02:04.687Z{"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-07-14T20:02:05.208264682Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1952025-07-14T20:02:04.715Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.241321551Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":33}
1962025-07-14T20:02:04.715Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.241407402Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1972025-07-14T20:02:04.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.241461663Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4550}
1982025-07-14T20:02:04.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.241903112Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
1992025-07-14T20:02:04.740Z{"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-07-14T20:02:05.241983744Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2002025-07-14T20:02:04.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.252404895Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":10}
2012025-07-14T20:02:04.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.252599429Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2022025-07-14T20:02:04.740Z{"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-07-14T20:02:05.25266791Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2032025-07-14T20:02:04.766Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.284571856Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":31}
2042025-07-14T20:02:04.766Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.284735179Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2052025-07-14T20:02:04.766Z{"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-07-14T20:02:05.28478234Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2062025-07-14T20:02:04.791Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.296417834Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":11}
2072025-07-14T20:02:04.791Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.296622168Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2082025-07-14T20:02:04.791Z{"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-07-14T20:02:05.29670314Z","target":"phd_framework::test_vm","line":804,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2092025-07-14T20:02:04.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.329894461Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":33}
2102025-07-14T20:02:04.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.330063504Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2112025-07-14T20:02:04.816Z{"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-07-14T20:02:05.330109325Z","target":"phd_framework::test_vm","line":804,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2122025-07-14T20:02:04.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.340563736Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":10}
2132025-07-14T20:02:04.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.340792531Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2142025-07-14T20:02:04.816Z{"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-07-14T20:02:05.340872013Z","target":"phd_framework::test_vm","line":804,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2152025-07-14T20:02:04.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.373788438Z","target":"phd_framework::test_vm","line":797,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":32}
2162025-07-14T20:02:04.873Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.37390703Z","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"}
2172025-07-14T20:02:04.873Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.373971821Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2182025-07-14T20:02:04.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.374018422Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2192025-07-14T20:02:04.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.374079154Z","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"}
2202025-07-14T20:02:04.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.374127055Z","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"}
2212025-07-14T20:02:04.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.374171855Z","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:9002","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2222025-07-14T20:02:04.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.374208686Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2232025-07-14T20:02:04.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 869","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.396626039Z","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"}
2242025-07-14T20:02:04.901Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.427304271Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":53}
2252025-07-14T20:02:04.928Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.427404063Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","target_id":"3b10d922-661f-4199-a31e-79a15ce17557"}
2262025-07-14T20:02:04.928Z{"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-07-14T20:02:05.427450154Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"b3daf23b-39ce-47b7-a3ac-ef2cc88a29bd","timeout_duration":"45s","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","target_id":"3b10d922-661f-4199-a31e-79a15ce17557"}
2272025-07-14T20:02:04.928Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.427497475Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","vm":"migration_from_base_and_back_lifecycle_0","target_id":"3b10d922-661f-4199-a31e-79a15ce17557","vm_id":"3b10d922-661f-4199-a31e-79a15ce17557"}
2282025-07-14T20:02:04.969Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.495303194Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 3b10d922-661f-4199-a31e-79a15ce17557, metadata: InstanceMetadata { project_id: ddae4c6b-3de8-4167-92ef-18642586b700, silo_id: 07bdc89b-5681-44e0-946a-167c4c07ddae, sled_id: 7552abf8-f2d5-4a84-a7be-1ff4a05822c6, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"7552abf8-f2d5-4a84-a7be-1ff4a05822c6\" }, name: \"phd-vm-3b10d922-661f-4199-a31e-79a15ce17557\" }, state: Migrating }","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","vm":"migration_from_base_and_back_lifecycle_0","target_id":"3b10d922-661f-4199-a31e-79a15ce17557","vm_id":"3b10d922-661f-4199-a31e-79a15ce17557"}
2292025-07-14T20:02:04.994Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.495400916Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","vm":"migration_from_base_and_back_lifecycle_0","target_id":"3b10d922-661f-4199-a31e-79a15ce17557","elapsed_milliseconds":67,"target":"migration_from_base_and_back_lifecycle_0","vm_id":"3b10d922-661f-4199-a31e-79a15ce17557"}
2302025-07-14T20:02:04.995Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:05.495452066Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","migration_id":"b3daf23b-39ce-47b7-a3ac-ef2cc88a29bd","target_id":"3b10d922-661f-4199-a31e-79a15ce17557"}
2312025-07-14T20:02:07.297Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:07.822889726Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7760}}"}
2322025-07-14T20:02:08.465Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:08.987090939Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","target_id":"3b10d922-661f-4199-a31e-79a15ce17557"}
2332025-07-14T20:02:08.465Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:08.98714704Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","migration_id":"b3daf23b-39ce-47b7-a3ac-ef2cc88a29bd","target_id":"3b10d922-661f-4199-a31e-79a15ce17557","elapsed_milliseconds":3491}
2342025-07-14T20:02:08.465Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:08.987185641Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","target_id":"3b10d922-661f-4199-a31e-79a15ce17557","elapsed_milliseconds":3559}
2352025-07-14T20:02:08.490Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:08.988756481Z","target":"phd_framework::test_vm","line":1054,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2362025-07-14T20:02:08.491Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:08.989000886Z","target":"phd_framework::test_vm","line":797,"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":"3b10d922-661f-4199-a31e-79a15ce17557"}
2372025-07-14T20:02:08.491Z{"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-07-14T20:02:08.989045657Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"3b10d922-661f-4199-a31e-79a15ce17557"}
2382025-07-14T20:02:08.491Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:08.98973764Z","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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2"}
2392025-07-14T20:02:08.544Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.070324216Z","target":"phd_framework::test_vm","line":1054,"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":"c60b0ad8-acfb-49fc-a6ba-b8300810e6e2","elapsed_milliseconds":81}
2402025-07-14T20:02:08.569Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.070717243Z","target":"phd_framework::test_vm","line":797,"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":"3b10d922-661f-4199-a31e-79a15ce17557","elapsed_milliseconds":81}
2412025-07-14T20:02:08.569Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.070856356Z","target":"phd_framework::test_vm","line":797,"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":"3b10d922-661f-4199-a31e-79a15ce17557"}
2422025-07-14T20:02:08.569Z{"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-07-14T20:02:09.070899697Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"3b10d922-661f-4199-a31e-79a15ce17557"}
2432025-07-14T20:02:08.594Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.099605661Z","target":"phd_framework::test_vm","line":797,"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":"3b10d922-661f-4199-a31e-79a15ce17557","elapsed_milliseconds":28}
2442025-07-14T20:02:08.594Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.099748034Z","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"}
2452025-07-14T20:02:08.594Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.099819735Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2462025-07-14T20:02:08.594Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.099864546Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2472025-07-14T20:02:08.594Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.099917927Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/22dd96ade0a3010628188fb9f4dc21b70dbd1abc21585df8007145a0b2c58b27/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2482025-07-14T20:02:08.594Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.099969408Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9004","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/22dd96ade0a3010628188fb9f4dc21b70dbd1abc21585df8007145a0b2c58b27/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2492025-07-14T20:02:08.594Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.100016379Z","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"}
2502025-07-14T20:02:08.620Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 871","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.1218274Z","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"}
2512025-07-14T20:02:08.645Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.152725207Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":52}
2522025-07-14T20:02:08.645Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.152795898Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"3b10d922-661f-4199-a31e-79a15ce17557","target_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2532025-07-14T20:02:08.645Z{"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-07-14T20:02:09.152837499Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"94aa3779-fac6-444b-b201-0e27262c2ba7","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"3b10d922-661f-4199-a31e-79a15ce17557","target_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2542025-07-14T20:02:08.645Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.15288073Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"3b10d922-661f-4199-a31e-79a15ce17557","vm":"migration_from_base_and_back_lifecycle_1","target_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","vm_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2552025-07-14T20:02:08.688Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.214275505Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 8bb4735f-b59a-439f-9cee-d557384a6dfd, metadata: InstanceMetadata { project_id: ddae4c6b-3de8-4167-92ef-18642586b700, silo_id: 07bdc89b-5681-44e0-946a-167c4c07ddae, sled_id: bcde8e45-6da4-41d3-8554-152b985d2069, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"bcde8e45-6da4-41d3-8554-152b985d2069\" }, name: \"phd-vm-8bb4735f-b59a-439f-9cee-d557384a6dfd\" }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"3b10d922-661f-4199-a31e-79a15ce17557","vm":"migration_from_base_and_back_lifecycle_1","target_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","vm_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2562025-07-14T20:02:08.714Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.214360307Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"3b10d922-661f-4199-a31e-79a15ce17557","vm":"migration_from_base_and_back_lifecycle_1","target_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","elapsed_milliseconds":61,"target":"migration_from_base_and_back_lifecycle_1","vm_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2572025-07-14T20:02:08.715Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:09.214402807Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"3b10d922-661f-4199-a31e-79a15ce17557","migration_id":"94aa3779-fac6-444b-b201-0e27262c2ba7","target_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2582025-07-14T20:02:10.975Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:11.501418146Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7807}}"}
2592025-07-14T20:02:11.608Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.133844214Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"3b10d922-661f-4199-a31e-79a15ce17557","target_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2602025-07-14T20:02:11.608Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.133892945Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"3b10d922-661f-4199-a31e-79a15ce17557","migration_id":"94aa3779-fac6-444b-b201-0e27262c2ba7","target_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","elapsed_milliseconds":2919}
2612025-07-14T20:02:11.608Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.133931456Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source_id":"3b10d922-661f-4199-a31e-79a15ce17557","target_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","elapsed_milliseconds":2981}
2622025-07-14T20:02:11.633Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.135510016Z","target":"phd_framework::test_vm","line":1054,"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":"3b10d922-661f-4199-a31e-79a15ce17557"}
2632025-07-14T20:02:11.633Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.13568852Z","target":"phd_framework::test_vm","line":797,"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":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2642025-07-14T20:02:11.633Z{"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-07-14T20:02:12.13573149Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2652025-07-14T20:02:11.633Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.136499925Z","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":"3b10d922-661f-4199-a31e-79a15ce17557"}
2662025-07-14T20:02:11.690Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.21602542Z","target":"phd_framework::test_vm","line":1054,"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":"3b10d922-661f-4199-a31e-79a15ce17557","elapsed_milliseconds":80}
2672025-07-14T20:02:11.715Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.216245265Z","target":"phd_framework::test_vm","line":797,"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":"8bb4735f-b59a-439f-9cee-d557384a6dfd","elapsed_milliseconds":80}
2682025-07-14T20:02:11.715Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.216355277Z","target":"phd_framework::test_vm","line":797,"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":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2692025-07-14T20:02:11.715Z{"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-07-14T20:02:12.216398878Z","target":"phd_framework::test_vm","line":804,"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_1","vm_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2702025-07-14T20:02:11.740Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.246481948Z","target":"phd_framework::test_vm","line":797,"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":"8bb4735f-b59a-439f-9cee-d557384a6dfd","elapsed_milliseconds":30}
2712025-07-14T20:02:11.741Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.24656992Z","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"}
2722025-07-14T20:02:11.741Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.246651342Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2732025-07-14T20:02:11.741Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.246709843Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2742025-07-14T20:02:11.741Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.246783454Z","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"}
2752025-07-14T20:02:11.741Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.246845106Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2762025-07-14T20:02:11.741Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.246877996Z","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"}
2772025-07-14T20:02:11.766Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 873","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.268479473Z","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"}
2782025-07-14T20:02:11.791Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.29940582Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":52}
2792025-07-14T20:02:11.791Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.299482142Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","target_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2802025-07-14T20:02:11.791Z{"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-07-14T20:02:12.299542513Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"f6dfe7d9-4847-485f-b345-efc9adf3479f","timeout_duration":"45s","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","target_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2812025-07-14T20:02:11.791Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.299587554Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","vm":"migration_from_base_and_back_lifecycle_2","target_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2","vm_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2822025-07-14T20:02:11.834Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.360190714Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 34d1d453-a7f3-498d-a2a8-6eff99d83eb2, metadata: InstanceMetadata { project_id: ddae4c6b-3de8-4167-92ef-18642586b700, silo_id: 07bdc89b-5681-44e0-946a-167c4c07ddae, sled_id: 12c4bc23-e5df-4128-8f45-ffa0d3a7d98b, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"12c4bc23-e5df-4128-8f45-ffa0d3a7d98b\" }, name: \"phd-vm-34d1d453-a7f3-498d-a2a8-6eff99d83eb2\" }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","vm":"migration_from_base_and_back_lifecycle_2","target_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2","vm_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2832025-07-14T20:02:11.859Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.360276615Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","vm":"migration_from_base_and_back_lifecycle_2","target_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2","elapsed_milliseconds":60,"target":"migration_from_base_and_back_lifecycle_2","vm_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2842025-07-14T20:02:11.859Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:12.360318646Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","migration_id":"f6dfe7d9-4847-485f-b345-efc9adf3479f","target_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2852025-07-14T20:02:14.146Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:14.671367859Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7854}}"}
2862025-07-14T20:02:14.671Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.197394253Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","target_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2872025-07-14T20:02:14.672Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.197439613Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","migration_id":"f6dfe7d9-4847-485f-b345-efc9adf3479f","target_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2","elapsed_milliseconds":2837}
2882025-07-14T20:02:14.672Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.197477934Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source_id":"8bb4735f-b59a-439f-9cee-d557384a6dfd","target_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2","elapsed_milliseconds":2897}
2892025-07-14T20:02:14.697Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.198903982Z","target":"phd_framework::test_vm","line":1054,"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":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2902025-07-14T20:02:14.697Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.199083955Z","target":"phd_framework::test_vm","line":797,"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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2912025-07-14T20:02:14.697Z{"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-07-14T20:02:15.199123996Z","target":"phd_framework::test_vm","line":804,"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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2922025-07-14T20:02:14.697Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.19982179Z","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":"8bb4735f-b59a-439f-9cee-d557384a6dfd"}
2932025-07-14T20:02:14.752Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.27806435Z","target":"phd_framework::test_vm","line":1054,"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":"8bb4735f-b59a-439f-9cee-d557384a6dfd","elapsed_milliseconds":79}
2942025-07-14T20:02:14.777Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.278282844Z","target":"phd_framework::test_vm","line":797,"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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2","elapsed_milliseconds":79}
2952025-07-14T20:02:14.777Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.278391696Z","target":"phd_framework::test_vm","line":797,"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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2962025-07-14T20:02:14.777Z{"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-07-14T20:02:15.278428927Z","target":"phd_framework::test_vm","line":804,"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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2972025-07-14T20:02:14.802Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.311507136Z","target":"phd_framework::test_vm","line":797,"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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2","elapsed_milliseconds":33}
2982025-07-14T20:02:14.802Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.311628178Z","target":"phd_framework::test_vm","line":1054,"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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
2992025-07-14T20:02:14.802Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.311862382Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3002025-07-14T20:02:14.802Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.311974335Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":14622}
3012025-07-14T20:02:14.802Z{"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-07-14T20:02:15.311976365Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3022025-07-14T20:02:14.802Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.312059726Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3032025-07-14T20:02:14.803Z{"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-07-14T20:02:15.313002904Z","target":"phd_framework::test_vm","line":1077,"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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
3042025-07-14T20:02:15.207Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.732416271Z","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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
3052025-07-14T20:02:15.284Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.810364106Z","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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
3062025-07-14T20:02:15.284Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.810412587Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-a0630370-7d2c-452e-8120-6f7abf3095c1\"]","verb":"destroy","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
3072025-07-14T20:02:15.310Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.829315202Z","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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
3082025-07-14T20:02:15.310Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.829352982Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-f1c2b1c7-7b4c-4c36-a6d5-5aa9786c4234\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2"}
3092025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.843832222Z","target":"phd_framework::test_vm","line":1054,"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":"34d1d453-a7f3-498d-a2a8-6eff99d83eb2","elapsed_milliseconds":532}
3102025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.843877263Z","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":84980}
3112025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.843977275Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":531}
3122025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.844017446Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3132025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.844043406Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3142025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.844067406Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3152025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.844191109Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
3162025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.84425736Z","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"}
3172025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.844293921Z","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"}
3182025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.844338542Z","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"}
3192025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.844381322Z","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"}
3202025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.851662963Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 740M 1.80T 740M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
3212025-07-14T20:02:15.335Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.851735544Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-489867d3-e8ae-4094-ae68-e08109d2c756\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::serial_history"}
3222025-07-14T20:02:15.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.864785236Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-489867d3-e8ae-4094-ae68-e08109d2c756\", \"phd-artifacts/phd-clone-f11560b2-ecea-4c58-8840-e173641ca2e9\"]","verb":"clone","path":"phd_tests::migrate::from_base::serial_history"}
3232025-07-14T20:02:15.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.877200136Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-f11560b2-ecea-4c58-8840-e173641ca2e9\"]","verb":"list","path":"phd_tests::migrate::from_base::serial_history"}
3242025-07-14T20:02:15.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.883164511Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-f11560b2-ecea-4c58-8840-e173641ca2e9 0B 1.80T 740M /phd-artifacts/phd-clone-f11560b2-ecea-4c58-8840-e173641ca2e9\n","path":"phd_tests::migrate::from_base::serial_history"}
3252025-07-14T20:02:15.361Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.88364712Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3262025-07-14T20:02:15.361Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.883698972Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
3272025-07-14T20:02:15.361Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.883754653Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/22dd96ade0a3010628188fb9f4dc21b70dbd1abc21585df8007145a0b2c58b27/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
3282025-07-14T20:02:15.361Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.883801263Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/22dd96ade0a3010628188fb9f4dc21b70dbd1abc21585df8007145a0b2c58b27/propolis-server\"","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::serial_history"}
3292025-07-14T20:02:15.361Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.883840464Z","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"}
3302025-07-14T20:02:15.387Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 882","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.905080974Z","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"}
3312025-07-14T20:02:15.412Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.936493131Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":52,"path":"phd_tests::migrate::from_base::serial_history"}
3322025-07-14T20:02:15.412Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.936598653Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3332025-07-14T20:02:15.473Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.99916202Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3342025-07-14T20:02:15.498Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.99964579Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: ad110a6e-2140-4ab7-9f27-e70d13f13e88, metadata: InstanceMetadata { project_id: 622877f6-05d9-4516-8351-3724b446ef3f, silo_id: c279f8ad-0c06-4881-9a4e-0e00106cc802, sled_id: 9544d460-306e-41f6-80d0-d2ef3386bfc4, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"9544d460-306e-41f6-80d0-d2ef3386bfc4\" }, name: \"phd-vm-ad110a6e-2140-4ab7-9f27-e70d13f13e88\" }, state: Creating }","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3352025-07-14T20:02:15.498Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.999724131Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","elapsed_milliseconds":63,"path":"phd_tests::migrate::from_base::serial_history"}
3362025-07-14T20:02:15.498Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.999783582Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3372025-07-14T20:02:15.499Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:15.999817613Z","target":"phd_framework::test_vm","line":470,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3382025-07-14T20:02:15.499Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:16.000440885Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::serial_history"}
3392025-07-14T20:02:15.499Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:16.000496056Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3402025-07-14T20:02:15.499Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:16.000534297Z","target":"phd_framework::test_vm","line":731,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3412025-07-14T20:02:15.499Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:16.000562317Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
3422025-07-14T20:02:15.499Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:16.000590868Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3432025-07-14T20:02:15.499Z{"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-07-14T20:02:16.000618978Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3442025-07-14T20:02:19.903Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.428955233Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","elapsed_milliseconds":4428,"path":"phd_tests::migrate::from_base::serial_history"}
3452025-07-14T20:02:19.904Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.429029635Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
3462025-07-14T20:02:19.904Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.429202728Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3472025-07-14T20:02:19.904Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.429245999Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3482025-07-14T20:02:19.904Z{"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-07-14T20:02:20.429274959Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3492025-07-14T20:02:19.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.447190585Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","elapsed_milliseconds":17,"path":"phd_tests::migrate::from_base::serial_history"}
3502025-07-14T20:02:19.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.447242136Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3512025-07-14T20:02:19.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.44741743Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3522025-07-14T20:02:19.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.44746271Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3532025-07-14T20:02:19.929Z{"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-07-14T20:02:20.447497021Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3542025-07-14T20:02:19.955Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.480294084Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history"}
3552025-07-14T20:02:19.955Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.480372976Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3562025-07-14T20:02:19.955Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.480424457Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4479,"path":"phd_tests::migrate::from_base::serial_history"}
3572025-07-14T20:02:19.955Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.480631531Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3582025-07-14T20:02:19.955Z{"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-07-14T20:02:20.480709352Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3592025-07-14T20:02:19.984Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.491045442Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history"}
3602025-07-14T20:02:19.984Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.491169444Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3612025-07-14T20:02:19.984Z{"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-07-14T20:02:20.491214165Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3622025-07-14T20:02:20.010Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.524569419Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::serial_history"}
3632025-07-14T20:02:20.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.52927556Z","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"}
3642025-07-14T20:02:20.010Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.529369872Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3652025-07-14T20:02:20.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.529408922Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3662025-07-14T20:02:20.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.529456013Z","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"}
3672025-07-14T20:02:20.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.529498874Z","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:9002","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::serial_history"}
3682025-07-14T20:02:20.010Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.529540325Z","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"}
3692025-07-14T20:02:20.035Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 883","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.55157872Z","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"}
3702025-07-14T20:02:20.060Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.583426045Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":54,"path":"phd_tests::migrate::from_base::serial_history"}
3712025-07-14T20:02:20.060Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.583495716Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","target":"migration_serial_history_base_lifecycle_0","target_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3722025-07-14T20:02:20.060Z{"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-07-14T20:02:20.583540087Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"37fedc3b-ac8c-481f-814a-1e9e70a9848f","source_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","target":"migration_serial_history_base_lifecycle_0","target_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3732025-07-14T20:02:20.060Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.583586588Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0","target_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","source":"migration_serial_history_base","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","path":"phd_tests::migrate::from_base::serial_history"}
3742025-07-14T20:02:20.119Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.645508743Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: f155fc9a-61b8-435b-9b1b-38903dbeacfa, metadata: InstanceMetadata { project_id: 622877f6-05d9-4516-8351-3724b446ef3f, silo_id: c279f8ad-0c06-4881-9a4e-0e00106cc802, sled_id: da2a17f3-2360-4319-aa4f-ca07efae3fde, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"da2a17f3-2360-4319-aa4f-ca07efae3fde\" }, name: \"phd-vm-f155fc9a-61b8-435b-9b1b-38903dbeacfa\" }, state: Migrating }","source_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0","target_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","source":"migration_serial_history_base","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","path":"phd_tests::migrate::from_base::serial_history"}
3752025-07-14T20:02:20.120Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.645598015Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","vm":"migration_serial_history_base_lifecycle_0","target_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","elapsed_milliseconds":61,"path":"phd_tests::migrate::from_base::serial_history"}
3762025-07-14T20:02:20.144Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:20.645642976Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","target":"migration_serial_history_base_lifecycle_0","target_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","source":"migration_serial_history_base","migration_id":"37fedc3b-ac8c-481f-814a-1e9e70a9848f","path":"phd_tests::migrate::from_base::serial_history"}
3772025-07-14T20:02:22.439Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:22.964752184Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7727}}"}
3782025-07-14T20:02:24.476Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.002243536Z","target":"phd_framework::test_vm","line":566,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","target":"migration_serial_history_base_lifecycle_0","target_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3792025-07-14T20:02:24.476Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.002296297Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","target":"migration_serial_history_base_lifecycle_0","target_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","source":"migration_serial_history_base","migration_id":"37fedc3b-ac8c-481f-814a-1e9e70a9848f","elapsed_milliseconds":4356,"path":"phd_tests::migrate::from_base::serial_history"}
3802025-07-14T20:02:24.477Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.002339677Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","target":"migration_serial_history_base_lifecycle_0","target_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","source":"migration_serial_history_base","elapsed_milliseconds":4418,"path":"phd_tests::migrate::from_base::serial_history"}
3812025-07-14T20:02:24.502Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.003977759Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3822025-07-14T20:02:24.502Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.005207133Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","path":"phd_tests::migrate::from_base::serial_history"}
3832025-07-14T20:02:24.556Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.081694819Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"ad110a6e-2140-4ab7-9f27-e70d13f13e88","elapsed_milliseconds":77,"path":"phd_tests::migrate::from_base::serial_history"}
3842025-07-14T20:02:24.581Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.083847071Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","path":"phd_tests::migrate::from_base::serial_history"}
3852025-07-14T20:02:24.581Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.083968443Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3862025-07-14T20:02:24.581Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.084062935Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9084}
3872025-07-14T20:02:24.581Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.084089656Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3882025-07-14T20:02:24.581Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.084145286Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3892025-07-14T20:02:24.581Z{"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-07-14T20:02:25.085180497Z","target":"phd_framework::test_vm","line":1077,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","path":"phd_tests::migrate::from_base::serial_history"}
3902025-07-14T20:02:25.073Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.598549397Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_serial_history_base_lifecycle_0","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","path":"phd_tests::migrate::from_base::serial_history"}
3912025-07-14T20:02:25.149Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.675092494Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","path":"phd_tests::migrate::from_base::serial_history"}
3922025-07-14T20:02:25.149Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.675161736Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-f11560b2-ecea-4c58-8840-e173641ca2e9\"]","verb":"destroy","vm":"migration_serial_history_base_lifecycle_0","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","path":"phd_tests::migrate::from_base::serial_history"}
3932025-07-14T20:02:25.174Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.694638252Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","path":"phd_tests::migrate::from_base::serial_history"}
3942025-07-14T20:02:25.174Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.694684123Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-489867d3-e8ae-4094-ae68-e08109d2c756\"]","vm":"migration_serial_history_base_lifecycle_0","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","path":"phd_tests::migrate::from_base::serial_history"}
3952025-07-14T20:02:25.199Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712317423Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","vm_id":"f155fc9a-61b8-435b-9b1b-38903dbeacfa","elapsed_milliseconds":628,"path":"phd_tests::migrate::from_base::serial_history"}
3962025-07-14T20:02:25.199Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712360024Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":9868,"path":"phd_tests::migrate::from_base::serial_history"}
3972025-07-14T20:02:25.199Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712517847Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":628}
3982025-07-14T20:02:25.199Z{"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-07-14T20:02:25.712584868Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3992025-07-14T20:02:25.199Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712616539Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
4002025-07-14T20:02:25.200Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712645169Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4012025-07-14T20:02:25.200Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712770662Z","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"}
4022025-07-14T20:02:25.200Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712834643Z","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"}
4032025-07-14T20:02:25.200Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712873204Z","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"}
4042025-07-14T20:02:25.200Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712909264Z","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"}
4052025-07-14T20:02:25.200Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.712948775Z","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"}
4062025-07-14T20:02:25.200Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.719616534Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 741M 1.80T 740M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4072025-07-14T20:02:25.200Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.719683915Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-6097d014-c8dd-4029-8739-2e16e486505e\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4082025-07-14T20:02:25.225Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.73079597Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-6097d014-c8dd-4029-8739-2e16e486505e\", \"phd-artifacts/phd-clone-98e4cf59-61d2-4ee5-81f3-482855005f82\"]","verb":"clone","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4092025-07-14T20:02:25.225Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.744999254Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-98e4cf59-61d2-4ee5-81f3-482855005f82\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4102025-07-14T20:02:25.250Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.751262645Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-98e4cf59-61d2-4ee5-81f3-482855005f82 0B 1.80T 740M /phd-artifacts/phd-clone-98e4cf59-61d2-4ee5-81f3-482855005f82\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4112025-07-14T20:02:25.250Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.751758225Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4122025-07-14T20:02:25.250Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.751807795Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4132025-07-14T20:02:25.250Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.751854106Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/22dd96ade0a3010628188fb9f4dc21b70dbd1abc21585df8007145a0b2c58b27/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4142025-07-14T20:02:25.250Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.751901037Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/22dd96ade0a3010628188fb9f4dc21b70dbd1abc21585df8007145a0b2c58b27/propolis-server\"","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4152025-07-14T20:02:25.250Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.751938098Z","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"}
4162025-07-14T20:02:25.250Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 892","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.773395352Z","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"}
4172025-07-14T20:02:25.291Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.805756107Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":53}
4182025-07-14T20:02:25.291Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.805829648Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4192025-07-14T20:02:25.343Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.86914778Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
4202025-07-14T20:02:25.368Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.869693871Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 61cd3929-54dc-46c4-9e82-b6812b96103a, metadata: InstanceMetadata { project_id: de6b661b-9527-485c-b72d-b1c4a525e48d, silo_id: 490ea6b2-cda7-45d1-8e75-6b76982ee120, sled_id: 15a2a632-5874-423f-b8a6-3118e0705d2b, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"15a2a632-5874-423f-b8a6-3118e0705d2b\" }, name: \"phd-vm-61cd3929-54dc-46c4-9e82-b6812b96103a\" }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4212025-07-14T20:02:25.368Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.869763103Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":63,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4222025-07-14T20:02:25.368Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.869828124Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4232025-07-14T20:02:25.368Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.869861864Z","target":"phd_framework::test_vm","line":470,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4242025-07-14T20:02:25.368Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.870507707Z","target":"phd_framework::test_vm","line":465,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":0,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4252025-07-14T20:02:25.368Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.870564918Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4262025-07-14T20:02:25.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.870603699Z","target":"phd_framework::test_vm","line":731,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","timeout_duration":"300s","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4272025-07-14T20:02:25.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.870632609Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4282025-07-14T20:02:25.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:25.87066119Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4292025-07-14T20:02:25.369Z{"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-07-14T20:02:25.87069006Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4302025-07-14T20:02:29.768Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.293166102Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4422,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4312025-07-14T20:02:29.768Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.293242643Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4322025-07-14T20:02:29.768Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.293460438Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4332025-07-14T20:02:29.768Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.293505078Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4342025-07-14T20:02:29.768Z{"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-07-14T20:02:30.293534469Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4352025-07-14T20:02:29.793Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.31069398Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":17,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4362025-07-14T20:02:29.793Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.310747461Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4372025-07-14T20:02:29.793Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.310917264Z","target":"phd_framework::test_vm","line":739,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4382025-07-14T20:02:29.793Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.310963665Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4392025-07-14T20:02:29.793Z{"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-07-14T20:02:30.310999356Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4402025-07-14T20:02:29.818Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.344182706Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4412025-07-14T20:02:29.818Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.344262328Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4422025-07-14T20:02:29.818Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.344299289Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4473}
4432025-07-14T20:02:29.844Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.344468112Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4442025-07-14T20:02:29.844Z{"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-07-14T20:02:30.344529093Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4452025-07-14T20:02:29.844Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.355003866Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4462025-07-14T20:02:29.844Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.35521177Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4472025-07-14T20:02:29.844Z{"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-07-14T20:02:30.355287551Z","target":"phd_framework::test_vm","line":804,"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_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4482025-07-14T20:02:29.869Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.388168466Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4492025-07-14T20:02:29.869Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.388306638Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4502025-07-14T20:02:29.869Z{"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-07-14T20:02:30.388360799Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4512025-07-14T20:02:29.894Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.398854202Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4522025-07-14T20:02:29.894Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.399048266Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4532025-07-14T20:02:29.894Z{"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-07-14T20:02:30.399116927Z","target":"phd_framework::test_vm","line":804,"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_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4542025-07-14T20:02:29.919Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.432117274Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4552025-07-14T20:02:29.919Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.432317068Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4562025-07-14T20:02:29.919Z{"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-07-14T20:02:30.432398469Z","target":"phd_framework::test_vm","line":804,"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_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4572025-07-14T20:02:29.919Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.443002224Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4582025-07-14T20:02:29.919Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.443205778Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4592025-07-14T20:02:29.919Z{"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-07-14T20:02:30.443272979Z","target":"phd_framework::test_vm","line":804,"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_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4602025-07-14T20:02:29.950Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.476423639Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4612025-07-14T20:02:29.951Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.476514361Z","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"}
4622025-07-14T20:02:29.975Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.476637383Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4632025-07-14T20:02:29.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.476701105Z","target":"phd_framework::test_vm","line":215,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4642025-07-14T20:02:29.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.476777006Z","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"}
4652025-07-14T20:02:29.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.476843058Z","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"}
4662025-07-14T20:02:29.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.476898279Z","target":"phd_framework::log_config","line":71,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4672025-07-14T20:02:29.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 893","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.49923767Z","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"}
4682025-07-14T20:02:30.005Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.531187627Z","target":"phd_framework::test_vm","line":197,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":54}
4692025-07-14T20:02:30.006Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.531255558Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0","target_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","source_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4702025-07-14T20:02:30.006Z{"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-07-14T20:02:30.531299369Z","target":"phd_framework::test_vm","line":532,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"e1c53cef-67d4-4c4e-b35b-fa53253f9680","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0","target_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","source_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4712025-07-14T20:02:30.031Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.53134526Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","target":"migration_from_base_lifecycle_0","target_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","source_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4722025-07-14T20:02:30.067Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.592587432Z","target":"phd_framework::test_vm","line":404,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 9758d8b3-2f79-44d3-ab46-82cdf9547bcb, metadata: InstanceMetadata { project_id: de6b661b-9527-485c-b72d-b1c4a525e48d, silo_id: 490ea6b2-cda7-45d1-8e75-6b76982ee120, sled_id: 4800f551-e884-4f8c-aa31-a94f2be1304d, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"4800f551-e884-4f8c-aa31-a94f2be1304d\" }, name: \"phd-vm-9758d8b3-2f79-44d3-ab46-82cdf9547bcb\" }, state: Migrating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","target":"migration_from_base_lifecycle_0","target_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","source_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4732025-07-14T20:02:30.092Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.592673003Z","target":"phd_framework::test_vm","line":306,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":61,"vm":"migration_from_base_lifecycle_0","target_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","source":"migration_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","target":"migration_from_base_lifecycle_0","source_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4742025-07-14T20:02:30.092Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:30.592716594Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","migration_id":"e1c53cef-67d4-4c4e-b35b-fa53253f9680","target":"migration_from_base_lifecycle_0","target_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","source_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4752025-07-14T20:02:32.382Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:32.908387426Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7760}}"}
4762025-07-14T20:02:33.482Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.005855631Z","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","source":"migration_from_base","target":"migration_from_base_lifecycle_0","target_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","source_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4772025-07-14T20:02:33.482Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.005920723Z","target":"phd_framework::test_vm","line":553,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":3413,"source":"migration_from_base","migration_id":"e1c53cef-67d4-4c4e-b35b-fa53253f9680","target":"migration_from_base_lifecycle_0","target_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","source_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4782025-07-14T20:02:33.482Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.005963613Z","target":"phd_framework::test_vm","line":499,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":3474,"source":"migration_from_base","target":"migration_from_base_lifecycle_0","target_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","source_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4792025-07-14T20:02:33.507Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.007477942Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4802025-07-14T20:02:33.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.007689037Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4812025-07-14T20:02:33.507Z{"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-07-14T20:02:34.007739967Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4822025-07-14T20:02:33.507Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.008550803Z","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_id":"61cd3929-54dc-46c4-9e82-b6812b96103a","vm":"migration_from_base"}
4832025-07-14T20:02:33.558Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.084326516Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":76,"vm":"migration_from_base","vm_id":"61cd3929-54dc-46c4-9e82-b6812b96103a"}
4842025-07-14T20:02:33.585Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.08455679Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":76,"vm":"migration_from_base_lifecycle_0","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb"}
4852025-07-14T20:02:33.585Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.084721174Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4862025-07-14T20:02:33.585Z{"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-07-14T20:02:34.084767254Z","target":"phd_framework::test_vm","line":804,"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_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4872025-07-14T20:02:33.610Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.118873723Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":34,"vm":"migration_from_base_lifecycle_0","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb"}
4882025-07-14T20:02:33.610Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.118949094Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4892025-07-14T20:02:33.610Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.119090287Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
4902025-07-14T20:02:33.610Z{"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-07-14T20:02:34.119134138Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
4912025-07-14T20:02:33.611Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.119196089Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
4922025-07-14T20:02:33.611Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.119206229Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8250}
4932025-07-14T20:02:33.611Z{"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-07-14T20:02:34.120168088Z","target":"phd_framework::test_vm","line":1077,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4942025-07-14T20:02:34.023Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.548472016Z","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_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4952025-07-14T20:02:34.102Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.62792597Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4962025-07-14T20:02:34.102Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.627994711Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-98e4cf59-61d2-4ee5-81f3-482855005f82\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4972025-07-14T20:02:34.127Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.649041098Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4982025-07-14T20:02:34.127Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.649077868Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-6097d014-c8dd-4029-8739-2e16e486505e\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb","vm":"migration_from_base_lifecycle_0"}
4992025-07-14T20:02:34.154Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.663716981Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":544,"vm":"migration_from_base_lifecycle_0","vm_id":"9758d8b3-2f79-44d3-ab46-82cdf9547bcb"}
5002025-07-14T20:02:34.154Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.663752291Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":8950}
5012025-07-14T20:02:34.154Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.663885984Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":544}
5022025-07-14T20:02:34.154Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.663949065Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5032025-07-14T20:02:34.154Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.663974946Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5042025-07-14T20:02:34.154Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 103.80s
5052025-07-14T20:02:34.154Z
5062025-07-14T20:02:34.154Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"buskin","pid":863,"time":"2025-07-14T20:02:34.664043377Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5072025-07-14T20:02:34.208Z
5082025-07-14T20:02:34.233Zreal 1:44.591825891
5092025-07-14T20:02:34.233Zuser 35.026452174
5102025-07-14T20:02:34.233Zsys 16.237682915
5112025-07-14T20:02:34.233Ztrap 0.003778761
5122025-07-14T20:02:34.233Ztflt 0.001347090
5132025-07-14T20:02:34.233Zdflt 0.000408053
5142025-07-14T20:02:34.233Zkflt 0.000262530
5152025-07-14T20:02:34.233Zlock 1:41:17.002279825
5162025-07-14T20:02:34.233Zslp 4:01.054831079
5172025-07-14T20:02:34.233Zlat 1.329201719
5182025-07-14T20:02:34.233Zstop 8.706553505
5192025-07-14T20:02:34.233Z+ failcount=0
5202025-07-14T20:02:34.233Z+ set -e
5212025-07-14T20:02:34.233Z+ 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
5222025-07-14T20:02:34.233ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5232025-07-14T20:02:34.233Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5242025-07-14T20:02:34.233Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log 233K
5252025-07-14T20:02:34.233Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5262025-07-14T20:02:34.233Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log 233K
5272025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5282025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log 146K
5292025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base_and_back.serial.log 7K
5302025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base_and_back.stderr.log 0K
5312025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base_and_back.stdout.log 140K
5322025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log 0K
5332025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log 145K
5342025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base.serial.log 7K
5352025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base.stderr.log 0K
5362025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_from_base.stdout.log 138K
5372025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log 0K
5382025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log 146K
5392025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_serial_history_base.serial.log 7K
5402025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_serial_history_base.stderr.log 0K
5412025-07-14T20:02:34.234Za /tmp/propolis-phd/migration_serial_history_base.stdout.log 139K
5422025-07-14T20:02:34.234Z+ exitcode=0
5432025-07-14T20:02:34.234Z+ '[' 0 -eq 0 ']'
5442025-07-14T20:02:34.234Z+ echo
5452025-07-14T20:02:34.234Z
5462025-07-14T20:02:34.234Z+ echo 'ALL TESTS PASSED'
5472025-07-14T20:02:34.234ZALL TESTS PASSED
5482025-07-14T20:02:34.234Z
5492025-07-14T20:02:34.234Z+ echo
5502025-07-14T20:02:34.234Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5512025-07-14T20:02:34.234Z+ read
5522025-07-14T20:02:34.234Z+ exit 0
5532025-07-14T20:02:34.234Zprocess exited: duration 117381 ms, exit code 0
 
5542025-07-14T20:02:34.311Zfound 2 output files
5552025-07-14T20:02:34.311Zuploading: /tmp/phd-runner.log (158353 bytes)
5562025-07-14T20:02:35.478Zuploaded: /tmp/phd-runner.log
5572025-07-14T20:02:35.478Zuploading: /tmp/phd-tmp-files.tar.gz (104271 bytes)
5582025-07-14T20:02:36.690Zuploaded: /tmp/phd-tmp-files.tar.gz