01KG3B9SQFDBR68H1ZH86DFF0W: 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: 01KG3BAM3X5CV1P5Q286ZQ146G

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-01-28T22:37:06.128Zjob dependencies complete; ready to run (waiting for 12 m 34 s)
22026-01-29T11:55:58.081Zjob assigned to worker 01KG4SPJPTG98Y042WY9C6QEPT [factory lab, sock/15866] (queued for 13 h 18 m 51 s)
32026-01-29T11:55:58.097Zxcvsh0tfvd xcvsh0tfvd xcvsh0tfvd xcvsh0tfvd xcvsh0tfvd xcvsh0tfvd xcvsh0tfvd xcvsh0tfvd
42026-01-29T11:55:58.149Zhttp://172.20.0.5:9969/ipxe/sock... ok
52026-01-29T11:55:58.184Zhttp://172.20.0.5:9969/os/sock/platform/i86pc/kernel/amd64/unix... ok
62026-01-29T11:55:58.217Zhttp://172.20.0.5:9969/os/sock/platform/i86pc/amd64/boot_archive... ok
72026-01-29T11:55:58.251Zhttp://172.20.0.5:9969/os/sock/platform/i86pc/amd64/boot_archive.hash... ok
82026-01-29T11:55:58.285Zhttp://172.20.0.5:9969/postboot/sock... ok
92026-01-29T11:55:58.319ZwcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U
102026-01-29T11:55:58.352ZWARNING: cpu0: failed to update microcode from version 0xa001133 to 0xa0011de
112026-01-29T11:55:58.386ZWARNING: cpu0: using older fallback microcode; update the system firmware
122026-01-29T11:55:58.421Zcpu0: microcode has been updated from version 0xa001133 to 0xa0011d5
132026-01-29T11:55:58.454ZOxide Helios Version helios-2.0.23698 64-bit
142026-01-29T11:55:58.488ZConfiguring devices.
152026-01-29T11:55:58.522Z##################################################
162026-01-29T11:55:58.555Z#### ############# ##
172026-01-29T11:55:58.588Z### ### ############ ##
182026-01-29T11:55:58.639Z## ### # ## ### ## Oxide Computer Company ##
192026-01-29T11:55:58.673Z## ## ## ### # ### ##
202026-01-29T11:55:58.706Z## # ### #### #### This Station Under ##
212026-01-29T11:55:58.740Z### ### #### # ### Computer Control ##
222026-01-29T11:55:58.773Z#### #### ### ## ##
232026-01-29T11:55:58.806Z##################################################
242026-01-29T11:55:58.840ZHostname: sock
252026-01-29T11:55:58.874ZLoading smf(7) service descriptions:
262026-01-29T11:55:59.306Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
272026-01-29T11:55:59.348Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
282026-01-29T11:55:59.348Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
292026-01-29T11:55:59.393Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
302026-01-29T11:55:59.417Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
312026-01-29T11:56:17.142Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
322026-01-29T11:56:17.142Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
332026-01-29T11:56:17.210Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
342026-01-29T11:56:17.234Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
352026-01-29T11:56:46.964Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
362026-01-29T11:56:46.988Zstarting task 0: "setup"
372026-01-29T11:56:46.988Z++ uname -s
382026-01-29T11:56:46.988Z+ kern=SunOS
392026-01-29T11:56:46.988Z+ build_user=build
402026-01-29T11:56:46.988Z+ build_uid=12345
412026-01-29T11:56:46.988Z+ work_dir=/work
422026-01-29T11:56:46.988Z+ input_dir=/input
432026-01-29T11:56:46.988Z+ [[ 0 == 12345 ]]
442026-01-29T11:56:46.988Z+ case "$kern" in
452026-01-29T11:56:46.988Z+ groupadd -g 12345 build
462026-01-29T11:56:46.988Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
472026-01-29T11:56:48.988Z+ zfs create -o mountpoint=/work rpool/work
482026-01-29T11:56:49.013Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
492026-01-29T11:56:49.013Z+ home_fs=zfs
502026-01-29T11:56:49.013Z+ [[ zfs == autofs ]]
512026-01-29T11:56:49.013Z+ mkdir -p /home/build
522026-01-29T11:56:49.013Z+ chown build:build /home/build /work
532026-01-29T11:56:51.012Z+ chmod 0700 /home/build /work
542026-01-29T11:56:51.036Zprocess exited: duration 4051 ms, exit code 0
 
552026-01-29T11:56:51.083Zstarting task 1: "authentication"
562026-01-29T11:56:51.128Zprocess exited: duration 44 ms, exit code 0
 
572026-01-29T11:56:51.176Zstarting task 2: "build"
582026-01-29T11:56:51.200Z+ indir=/input
592026-01-29T11:56:51.200Z+ indir_suffix='phd-build/out/*.tar.gz'
602026-01-29T11:56:51.200Z+ phddir=/work/phd-test
612026-01-29T11:56:51.200Z+ pfexec zpool create -f phd-artifacts c1t1d0 c2t1d0
622026-01-29T11:56:51.355Z+ artifactdir=/phd-artifacts
632026-01-29T11:56:51.355Z+ banner Inputs
642026-01-29T11:56:51.379Z ###
652026-01-29T11:56:51.379Z # # # ##### # # ##### ####
662026-01-29T11:56:51.379Z # ## # # # # # # #
672026-01-29T11:56:51.379Z # # # # # # # # # ####
682026-01-29T11:56:51.379Z # # # # ##### # # # #
692026-01-29T11:56:51.379Z # # ## # # # # # #
702026-01-29T11:56:51.379Z ### # # # #### # ####
712026-01-29T11:56:51.379Z
722026-01-29T11:56:51.379Z+ find /input -ls
732026-01-29T11:56:51.379Z 34 1 drwxr-xr-x 3 root root 3 Jan 29 11:55 /input
742026-01-29T11:56:51.379Z 2 1 drwxr-xr-x 3 root root 3 Jan 29 11:55 /input/phd-build
752026-01-29T11:56:51.379Z 3 2 drwxr-xr-x 2 root root 7 Jan 29 11:56 /input/phd-build/out
762026-01-29T11:56:51.379Z 256 173209 -rw-r--r-- 1 root root 177280128 Jan 29 11:56 /input/phd-build/out/propolis-server-debug.tar.gz
772026-01-29T11:56:51.379Z 130 103004 -rw-r--r-- 1 root root 105405388 Jan 29 11:56 /input/phd-build/out/phd-runner.tar.gz
782026-01-29T11:56:51.379Z 131 1 -rw-r--r-- 1 root root 65 Jan 29 11:56 /input/phd-build/out/propolis-server-debug.sha256.txt
792026-01-29T11:56:51.379Z 129 1 -rw-r--r-- 1 root root 65 Jan 29 11:55 /input/phd-build/out/phd-runner.sha256.txt
802026-01-29T11:56:51.379Z 128 3 -rw-r--r-- 1 root root 2402 Jan 29 11:55 /input/phd-build/out/phd-run-with-args.sh
812026-01-29T11:56:51.379Z+ rm -rf /work/phd-test
822026-01-29T11:56:51.380Z+ mkdir /work/phd-test
832026-01-29T11:56:51.380Z+ for p in $indir/$indir_suffix
842026-01-29T11:56:51.380Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
852026-01-29T11:56:51.380Ztar: blocksize = 10
862026-01-29T11:56:53.937ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
872026-01-29T11:56:53.937Zx phd-runner, 374291080 bytes, 731038 tape blocks
882026-01-29T11:56:53.937Zx artifacts.toml, 548 bytes, 2 tape blocks
892026-01-29T11:56:53.961Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
902026-01-29T11:56:56.078Z+ for f in $(tar tf "$p")
912026-01-29T11:56:56.078Z+ chmod +x /work/phd-test/phd-runner
922026-01-29T11:56:56.102Z+ for f in $(tar tf "$p")
932026-01-29T11:56:56.102Z+ chmod +x /work/phd-test/artifacts.toml
942026-01-29T11:56:56.103Z+ for p in $indir/$indir_suffix
952026-01-29T11:56:56.103Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
962026-01-29T11:57:00.208ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
972026-01-29T11:57:00.208Zx propolis-server, 677022984 bytes, 1322311 tape blocks
982026-01-29T11:57:00.239Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
992026-01-29T11:57:03.926Z+ for f in $(tar tf "$p")
1002026-01-29T11:57:03.926Z+ chmod +x /work/phd-test/propolis-server
1012026-01-29T11:57:03.950Z+ ls /work/phd-test
1022026-01-29T11:57:03.950Zartifacts.toml
1032026-01-29T11:57:03.950Zphd-runner
1042026-01-29T11:57:03.950Zpropolis-server
1052026-01-29T11:57:03.950Z+ banner Setup
1062026-01-29T11:57:03.950Z #####
1072026-01-29T11:57:03.950Z# # ###### ##### # # #####
1082026-01-29T11:57:03.950Z# # # # # # #
1092026-01-29T11:57:03.950Z ##### ##### # # # # #
1102026-01-29T11:57:03.950Z # # # # # #####
1112026-01-29T11:57:03.950Z# # # # # # #
1122026-01-29T11:57:03.950Z ##### ###### # #### #
1132026-01-29T11:57:03.951Z
1142026-01-29T11:57:03.951Z+ tmpdir=/tmp/propolis-phd
1152026-01-29T11:57:03.951Z+ '[' '!' -d /tmp/propolis-phd ']'
1162026-01-29T11:57:03.951Z+ mkdir /tmp/propolis-phd
1172026-01-29T11:57:03.951Z+ pfexec /usr/lib/rsrvrctl -s 4096
1182026-01-29T11:57:04.573Z+ banner Tests
1192026-01-29T11:57:04.598Z#######
1202026-01-29T11:57:04.598Z # ###### #### ##### ####
1212026-01-29T11:57:04.598Z # # # # #
1222026-01-29T11:57:04.598Z # ##### #### # ####
1232026-01-29T11:57:04.598Z # # # # #
1242026-01-29T11:57:04.598Z # # # # # # #
1252026-01-29T11:57:04.598Z # ###### #### # ####
1262026-01-29T11:57:04.598Z
1272026-01-29T11:57:04.598Z+ runner=/work/phd-test/phd-runner
1282026-01-29T11:57:04.598Z+ artifacts=/work/phd-test/artifacts.toml
1292026-01-29T11:57:04.598Z+ propolis=/work/phd-test/propolis-server
1302026-01-29T11:57:04.598Z+ ls /work/phd-test/phd-runner
1312026-01-29T11:57:04.598Z/work/phd-test/phd-runner
1322026-01-29T11:57:04.598Z+ ls /work/phd-test/artifacts.toml
1332026-01-29T11:57:04.598Z/work/phd-test/artifacts.toml
1342026-01-29T11:57:04.598Z+ ls /work/phd-test/propolis-server
1352026-01-29T11:57:04.598Z/work/phd-test/propolis-server
1362026-01-29T11:57:04.598Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1372026-01-29T11:57:04.598Z+ set +e
1382026-01-29T11:57:04.598Z+ RUST_BACKTRACE=1
1392026-01-29T11:57:04.598Z+ RUST_LOG=info,phd=debug
1402026-01-29T11:57:04.598Z+ 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
1412026-01-29T11:57:04.598Z+ tee /tmp/phd-runner.log
1422026-01-29T11:57:04.623Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:04.573037585Z","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 }"}
1432026-01-29T11:57:04.623Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:04.576019746Z","target":"phd_framework::artifacts::store","line":219,"file":"phd-tests/framework/src/artifacts/store.rs","store":"Store { local_dir: \"/phd-artifacts\", artifacts: {\"alpine\": Mutex { data: StoredArtifact { description: Artifact { filename: \"alpine.iso\", kind: GuestOs(Alpine), source: RemoteServer { sha256: \"ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1\" }, untar: None }, cached_path: None } }, \"ovmf\": Mutex { data: StoredArtifact { description: Artifact { filename: \"OVMF_CODE.fd\", kind: Bootrom, source: Buildomat(BuildomatArtifact { repo: Repo(\"oxidecomputer/edk2\"), series: Series(\"image_debug\"), commit: Commit(\"907a5fd1763ce5ddd74001261e5b52cd200a25f9\"), sha256: \"ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb\" }), untar: None }, cached_path: None } }}, downloader: DownloadConfig { timeout: 600s, buildomat_backoff: ExponentialBackoff { current_interval: 1s, initial_interval: 1s, randomization_factor: 0.5, multiplier: 1.5, max_interval: 60s, start_time: Instant { tv_sec: 233, tv_nsec: 334833672 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1442026-01-29T11:57:04.623Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:04.576106578Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1452026-01-29T11:57:04.623Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:04.57622785Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"7103cd3a3d7b0112d2949dd135db06fef0c156bb"}
1462026-01-29T11:57:04.623Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:04.576477406Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/7103cd3a3d7b0112d2949dd135db06fef0c156bb/crucible-nightly.sha256.txt"}
1472026-01-29T11:57:04.769Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:04.7281568Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1482026-01-29T11:57:05.226Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.184174994Z","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/ffcc27be57652b6c63595e254b59ef95c33d8cc1/propolis-server.sha256.txt"}
1492026-01-29T11:57:05.342Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.300468535Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1502026-01-29T11:57:05.367Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.300637028Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1512026-01-29T11:57:05.367Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.300927354Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1522026-01-29T11:57:05.367Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.301143029Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1532026-01-29T11:57:05.367Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.301178089Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1542026-01-29T11:57:05.367Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.30120551Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1552026-01-29T11:57:05.367Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.301505956Z","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"}
1562026-01-29T11:57:05.367Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.301893504Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1572026-01-29T11:57:05.368Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.302133369Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/907a5fd1763ce5ddd74001261e5b52cd200a25f9/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1582026-01-29T11:57:05.916Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.874348402Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1592026-01-29T11:57:05.940Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:05.874513635Z","target":"phd_framework::artifacts::store","line":614,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1602026-01-29T11:57:30.346Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.304847769Z","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"}
1612026-01-29T11:57:30.346Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.304980072Z","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"}
1622026-01-29T11:57:30.371Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.3122217Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2.01M 1.80T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1632026-01-29T11:57:30.371Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.312516966Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-2f0ec5c7-f185-4f64-9274-8ebfc759a666\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1642026-01-29T11:57:30.399Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.358077629Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-2f0ec5c7-f185-4f64-9274-8ebfc759a666\", \"phd-artifacts/phd-clone-92b217f9-55e8-4915-acfe-f44091cebdec\"]","verb":"clone","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-01-29T11:57:30.423Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.370464772Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-92b217f9-55e8-4915-acfe-f44091cebdec\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1662026-01-29T11:57:30.424Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.376819703Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-92b217f9-55e8-4915-acfe-f44091cebdec 0B 1.80T 48.9M /phd-artifacts/phd-clone-92b217f9-55e8-4915-acfe-f44091cebdec\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1672026-01-29T11:57:30.424Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.377762042Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1682026-01-29T11:57:30.424Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.377821343Z","target":"phd_framework::test_vm","line":217,"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"}
1692026-01-29T11:57:30.424Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.377883184Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/088bb567bfaa3a7882ea2569cd9d83b22d77e1f0a4a522e66ac8616f0678446d/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1702026-01-29T11:57:30.424Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:57:30.377942636Z","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/ffcc27be57652b6c63595e254b59ef95c33d8cc1/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1712026-01-29T11:58:00.757Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:00.715544596Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/088bb567bfaa3a7882ea2569cd9d83b22d77e1f0a4a522e66ac8616f0678446d/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1722026-01-29T11:58:00.757Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:00.715628758Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1732026-01-29T11:58:17.736Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:17.695140752Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/088bb567bfaa3a7882ea2569cd9d83b22d77e1f0a4a522e66ac8616f0678446d/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1742026-01-29T11:58:17.737Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:17.695252314Z","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"}
1752026-01-29T11:58:17.805Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 859","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:17.763787237Z","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"}
1762026-01-29T11:58:17.829Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:17.764233846Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1772026-01-29T11:58:17.829Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:17.76541242Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1782026-01-29T11:58:17.829Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:17.765736886Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":47387,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1792026-01-29T11:58:18.218Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.176687128Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1802026-01-29T11:58:18.242Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.177610937Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 83c06b8f-06d3-4325-9337-faa8b627657b, name: \"phd-vm-83c06b8f-06d3-4325-9337-faa8b627657b\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 1ba25a9c-674f-43bf-ace8-67645e213506, project_id: f7f5c1b8-fd87-48ac-b992-a966fa453571, sled_id: 356d933d-79c5-4487-a4ef-140a1286d6de, sled_serial: \"356d933d-79c5-4487-a4ef-140a1286d6de\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1812026-01-29T11:58:18.242Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.17773011Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1822026-01-29T11:58:18.242Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.17777436Z","target":"phd_framework::test_vm","line":472,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1832026-01-29T11:58:18.242Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.178452454Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1842026-01-29T11:58:18.242Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.178533096Z","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"}
1852026-01-29T11:58:18.242Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.178597637Z","target":"phd_framework::test_vm","line":731,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1862026-01-29T11:58:18.242Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.178647528Z","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"}
1872026-01-29T11:58:18.242Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.178711919Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1882026-01-29T11:58:18.242Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:18.17876084Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1892026-01-29T11:58:22.603Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.561539462Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4382,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1902026-01-29T11:58:22.603Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.561624273Z","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"}
1912026-01-29T11:58:22.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.561968891Z","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"}
1922026-01-29T11:58:22.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.562020272Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1932026-01-29T11:58:22.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.562064562Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1942026-01-29T11:58:22.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.580804746Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1952026-01-29T11:58:22.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.580868557Z","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"}
1962026-01-29T11:58:22.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.581105622Z","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"}
1972026-01-29T11:58:22.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.581152153Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1982026-01-29T11:58:22.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.581188894Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1992026-01-29T11:58:22.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.613766461Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2002026-01-29T11:58:22.655Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.613876323Z","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"}
2012026-01-29T11:58:22.680Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.613943584Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4435,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2022026-01-29T11:58:22.680Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.614358053Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2032026-01-29T11:58:22.680Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.614474525Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2042026-01-29T11:58:22.680Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.625629934Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2052026-01-29T11:58:22.680Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.625765246Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2062026-01-29T11:58:22.680Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.625821758Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2072026-01-29T11:58:22.704Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.648235796Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2082026-01-29T11:58:22.704Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.64839688Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2092026-01-29T11:58:22.705Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.648454171Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2102026-01-29T11:58:22.705Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.658782802Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2112026-01-29T11:58:22.705Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.658983226Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2122026-01-29T11:58:22.705Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.659070918Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2132026-01-29T11:58:22.729Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.681397415Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2142026-01-29T11:58:22.729Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.681535348Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2152026-01-29T11:58:22.729Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.681592099Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2162026-01-29T11:58:22.753Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.69188894Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2172026-01-29T11:58:22.753Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.692098034Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2182026-01-29T11:58:22.754Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.692198366Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2192026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.714572304Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2202026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.714669746Z","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"}
2212026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.714763788Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2222026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.714821849Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2232026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.714938092Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","sha256":"None","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2242026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.715000083Z","target":"phd_framework::artifacts::store","line":69,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2252026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.715055814Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2262026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.715108375Z","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"}
2272026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 860","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.733875519Z","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"}
2282026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.734131124Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":19,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2292026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.734222237Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","source":"migration_from_base","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2302026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.734326239Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"49f811a6-02b3-47fc-8f9c-54c1670d5b0d","timeout_duration":"45s","target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","source":"migration_from_base","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2312026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.73440146Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","source":"migration_from_base","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2322026-01-29T11:58:22.778Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:22.734984452Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","vm":"migration_from_base_lifecycle_0","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","source":"migration_from_base","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2332026-01-29T11:58:23.344Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:23.302298045Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 407d19b0-5c93-4cc0-a2aa-581e2aea07b9, name: \"phd-vm-407d19b0-5c93-4cc0-a2aa-581e2aea07b9\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 1ba25a9c-674f-43bf-ace8-67645e213506, project_id: f7f5c1b8-fd87-48ac-b992-a966fa453571, sled_id: 7fcccfa1-fe19-49c3-8eb6-96c2a0fcef0f, sled_serial: \"7fcccfa1-fe19-49c3-8eb6-96c2a0fcef0f\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm":"migration_from_base_lifecycle_0","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","source":"migration_from_base","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2342026-01-29T11:58:23.368Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:23.302457538Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","migration_id":"49f811a6-02b3-47fc-8f9c-54c1670d5b0d","source":"migration_from_base","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2352026-01-29T11:58:25.576Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.534899513Z","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}}"}
2362026-01-29T11:58:25.774Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.73258926Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","source":"migration_from_base","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2372026-01-29T11:58:25.774Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.732650711Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":2430,"target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","migration_id":"49f811a6-02b3-47fc-8f9c-54c1670d5b0d","source":"migration_from_base","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2382026-01-29T11:58:25.798Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.734144742Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2392026-01-29T11:58:25.798Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.734451438Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2402026-01-29T11:58:25.798Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.734503149Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2412026-01-29T11:58:25.798Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.735288955Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2422026-01-29T11:58:25.857Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.816217142Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":81,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2432026-01-29T11:58:25.882Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.816465877Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":8052,"vm_id":"83c06b8f-06d3-4325-9337-faa8b627657b","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2442026-01-29T11:58:25.882Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.81661714Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":82,"vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2452026-01-29T11:58:25.882Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.816830154Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2462026-01-29T11:58:25.882Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.816900616Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2472026-01-29T11:58:25.906Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.84446201Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":27,"vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2482026-01-29T11:58:25.906Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.844597393Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2492026-01-29T11:58:25.906Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.844846338Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2502026-01-29T11:58:25.906Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.844988721Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":7668}
2512026-01-29T11:58:25.906Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.845114833Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
2522026-01-29T11:58:25.906Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.845216396Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2532026-01-29T11:58:25.906Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:25.845872179Z","target":"phd_framework::test_vm","line":1077,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-01-29T11:58:26.233Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.191902952Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-01-29T11:58:26.311Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.269722415Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-01-29T11:58:26.311Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.269809276Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-92b217f9-55e8-4915-acfe-f44091cebdec\"]","verb":"destroy","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2572026-01-29T11:58:26.336Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.288946198Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2582026-01-29T11:58:26.336Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.289005799Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-2f0ec5c7-f185-4f64-9274-8ebfc759a666\"]","verb":"destroy","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2592026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.301700499Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":456,"vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2602026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.301856662Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":456}
2612026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.301868353Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","elapsed_milliseconds":3567,"source":"migration_from_base","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9"}
2622026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.301901813Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
2632026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.301915144Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"407d19b0-5c93-4cc0-a2aa-581e2aea07b9","elapsed_milliseconds":3567,"source":"migration_from_base","target":"migration_from_base_lifecycle_0","source_id":"83c06b8f-06d3-4325-9337-faa8b627657b","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2642026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.301929824Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2652026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.301949174Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":81000,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2662026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.301957545Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2672026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.302037706Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2682026-01-29T11:58:26.360Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.302108108Z","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"}
2692026-01-29T11:58:26.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.302154198Z","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"}
2702026-01-29T11:58:26.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.302194799Z","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"}
2712026-01-29T11:58:26.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.30224282Z","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"}
2722026-01-29T11:58:26.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.308758784Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 865M 1.80T 864M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2732026-01-29T11:58:26.361Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.308837305Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-b75ddf41-6f38-4a1f-bc46-2d7566433a88\"]","path":"phd_tests::migrate::from_base::serial_history"}
2742026-01-29T11:58:26.385Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.320035835Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-b75ddf41-6f38-4a1f-bc46-2d7566433a88\", \"phd-artifacts/phd-clone-e166221f-5e4f-4697-9333-d3c3dc816e9f\"]","verb":"clone","path":"phd_tests::migrate::from_base::serial_history"}
2752026-01-29T11:58:26.385Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.331632352Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-e166221f-5e4f-4697-9333-d3c3dc816e9f\"]","path":"phd_tests::migrate::from_base::serial_history"}
2762026-01-29T11:58:26.385Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.33839584Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-e166221f-5e4f-4697-9333-d3c3dc816e9f 0B 1.80T 864M /phd-artifacts/phd-clone-e166221f-5e4f-4697-9333-d3c3dc816e9f\n","path":"phd_tests::migrate::from_base::serial_history"}
2772026-01-29T11:58:26.385Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.33889349Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2782026-01-29T11:58:26.385Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.338954112Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
2792026-01-29T11:58:26.385Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.339012023Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/088bb567bfaa3a7882ea2569cd9d83b22d77e1f0a4a522e66ac8616f0678446d/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2802026-01-29T11:58:26.385Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.339070684Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/088bb567bfaa3a7882ea2569cd9d83b22d77e1f0a4a522e66ac8616f0678446d/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
2812026-01-29T11:58:26.385Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.339127265Z","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"}
2822026-01-29T11:58:26.410Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 869","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.357549742Z","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"}
2832026-01-29T11:58:26.410Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.357783647Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::serial_history"}
2842026-01-29T11:58:26.410Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.357868999Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
2852026-01-29T11:58:26.410Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.358469381Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
2862026-01-29T11:58:26.818Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.777055959Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2872026-01-29T11:58:26.843Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.778244114Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: e31380f2-b567-4bb2-8f51-eb198c04a518, name: \"phd-vm-e31380f2-b567-4bb2-8f51-eb198c04a518\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 558db882-5fdf-4094-a4d7-f53dd97d4bd6, project_id: 205959e4-8060-4f4d-bdae-df08090a9675, sled_id: 2635a4bd-9f7a-49d3-8533-9a3314ed79fc, sled_serial: \"2635a4bd-9f7a-49d3-8533-9a3314ed79fc\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
2882026-01-29T11:58:26.843Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.778359006Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
2892026-01-29T11:58:26.843Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.778403947Z","target":"phd_framework::test_vm","line":472,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
2902026-01-29T11:58:26.843Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.779099261Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
2912026-01-29T11:58:26.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.779163453Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2922026-01-29T11:58:26.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.779209023Z","target":"phd_framework::test_vm","line":731,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","timeout_duration":"300s","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","path":"phd_tests::migrate::from_base::serial_history"}
2932026-01-29T11:58:26.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.779245944Z","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"}
2942026-01-29T11:58:26.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.779279445Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
2952026-01-29T11:58:26.843Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:26.779315886Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
2962026-01-29T11:58:31.163Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.121863673Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4342,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
2972026-01-29T11:58:31.163Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.121935965Z","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"}
2982026-01-29T11:58:31.188Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.122107698Z","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"}
2992026-01-29T11:58:31.188Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.122157499Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3002026-01-29T11:58:31.188Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.12220157Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3012026-01-29T11:58:31.188Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.1412489Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":19,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3022026-01-29T11:58:31.188Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.141389753Z","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"}
3032026-01-29T11:58:31.188Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.141785211Z","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"}
3042026-01-29T11:58:31.188Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.141871173Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3052026-01-29T11:58:31.188Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.141914634Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3062026-01-29T11:58:31.216Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.174738035Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3072026-01-29T11:58:31.216Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.174840067Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3082026-01-29T11:58:31.240Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.174905939Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4395,"path":"phd_tests::migrate::from_base::serial_history"}
3092026-01-29T11:58:31.240Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.175126303Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3102026-01-29T11:58:31.241Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.175218995Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3112026-01-29T11:58:31.241Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.185576937Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3122026-01-29T11:58:31.241Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.18571494Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3132026-01-29T11:58:31.241Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.185773751Z","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::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3142026-01-29T11:58:31.265Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.218634364Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3152026-01-29T11:58:31.265Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.223444362Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_serial_history_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::serial_history"}
3162026-01-29T11:58:31.265Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.223548965Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3172026-01-29T11:58:31.265Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.223593545Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
3182026-01-29T11:58:31.265Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.223652407Z","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"}
3192026-01-29T11:58:31.265Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.223699557Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history"}
3202026-01-29T11:58:31.265Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.223742118Z","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"}
3212026-01-29T11:58:31.289Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 870","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.243321469Z","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"}
3222026-01-29T11:58:31.289Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.243594055Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":20,"path":"phd_tests::migrate::from_base::serial_history"}
3232026-01-29T11:58:31.289Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.243682657Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","target":"migration_serial_history_base_lifecycle_0"}
3242026-01-29T11:58:31.289Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.243760518Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"4aebf913-ff69-4c08-aa1e-c0a72581c098","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","target":"migration_serial_history_base_lifecycle_0"}
3252026-01-29T11:58:31.289Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.24383202Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","vm":"migration_serial_history_base_lifecycle_0","source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","target":"migration_serial_history_base_lifecycle_0"}
3262026-01-29T11:58:31.289Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.244408952Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","vm":"migration_serial_history_base_lifecycle_0","source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","target":"migration_serial_history_base_lifecycle_0"}
3272026-01-29T11:58:31.649Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.607695888Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 88522691-f998-49f8-b252-aa1e4ab2b19d, name: \"phd-vm-88522691-f998-49f8-b252-aa1e4ab2b19d\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 558db882-5fdf-4094-a4d7-f53dd97d4bd6, project_id: 205959e4-8060-4f4d-bdae-df08090a9675, sled_id: 38c18343-13ca-4d83-a136-bca11b0f43ba, sled_serial: \"38c18343-13ca-4d83-a136-bca11b0f43ba\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","vm":"migration_serial_history_base_lifecycle_0","source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","target":"migration_serial_history_base_lifecycle_0"}
3282026-01-29T11:58:31.649Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:31.607854651Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"4aebf913-ff69-4c08-aa1e-c0a72581c098","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","target":"migration_serial_history_base_lifecycle_0"}
3292026-01-29T11:58:33.900Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:33.858909718Z","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}}"}
3302026-01-29T11:58:34.173Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.131344314Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","target":"migration_serial_history_base_lifecycle_0"}
3312026-01-29T11:58:34.173Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.131397675Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"4aebf913-ff69-4c08-aa1e-c0a72581c098","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","elapsed_milliseconds":2523,"source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","target":"migration_serial_history_base_lifecycle_0"}
3322026-01-29T11:58:34.197Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.133381186Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3332026-01-29T11:58:34.198Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.134711203Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3342026-01-29T11:58:34.257Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.215437775Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":81,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3352026-01-29T11:58:34.305Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.215607029Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":7857,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"e31380f2-b567-4bb2-8f51-eb198c04a518"}
3362026-01-29T11:58:34.330Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.218168861Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d"}
3372026-01-29T11:58:34.330Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.218331705Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3382026-01-29T11:58:34.330Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.218418656Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3392026-01-29T11:58:34.330Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.218433137Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":7441}
3402026-01-29T11:58:34.330Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.218477798Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3412026-01-29T11:58:34.330Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.219427617Z","target":"phd_framework::test_vm","line":1077,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d"}
3422026-01-29T11:58:34.731Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.689914518Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d"}
3432026-01-29T11:58:34.807Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.766270781Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d"}
3442026-01-29T11:58:34.807Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.766355242Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-e166221f-5e4f-4697-9333-d3c3dc816e9f\"]","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d"}
3452026-01-29T11:58:34.831Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.785271039Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d"}
3462026-01-29T11:58:34.831Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.78531598Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-b75ddf41-6f38-4a1f-bc46-2d7566433a88\"]","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d"}
3472026-01-29T11:58:34.855Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799007571Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":580,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d"}
3482026-01-29T11:58:34.855Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799190955Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":580}
3492026-01-29T11:58:34.855Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799194435Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","vm_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","elapsed_milliseconds":3555,"path":"phd_tests::migrate::from_base::serial_history","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0"}
3502026-01-29T11:58:34.855Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799257576Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3555,"path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"88522691-f998-49f8-b252-aa1e4ab2b19d","source_id":"e31380f2-b567-4bb2-8f51-eb198c04a518","target":"migration_serial_history_base_lifecycle_0"}
3512026-01-29T11:58:34.855Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799275696Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3522026-01-29T11:58:34.855Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799292726Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":8497,"path":"phd_tests::migrate::from_base::serial_history"}
3532026-01-29T11:58:34.856Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799315687Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3542026-01-29T11:58:34.856Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799349318Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3552026-01-29T11:58:34.856Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.79945558Z","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"}
3562026-01-29T11:58:34.856Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799543282Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3572026-01-29T11:58:34.856Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799592213Z","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"}
3582026-01-29T11:58:34.856Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799645774Z","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"}
3592026-01-29T11:58:34.856Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.799698185Z","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::migration_from_base_and_back"}
3602026-01-29T11:58:34.856Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.805942913Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 865M 1.80T 864M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3612026-01-29T11:58:34.856Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.806056035Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-1f358b74-5043-427f-a44b-c344e0368e9c\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3622026-01-29T11:58:34.880Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.816116731Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-1f358b74-5043-427f-a44b-c344e0368e9c\", \"phd-artifacts/phd-clone-c22379e7-3cd7-4b13-8098-926ecd3d00b7\"]","verb":"clone","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3632026-01-29T11:58:34.880Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.827896892Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-c22379e7-3cd7-4b13-8098-926ecd3d00b7\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3642026-01-29T11:58:34.880Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.834903026Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-c22379e7-3cd7-4b13-8098-926ecd3d00b7 0B 1.80T 864M /phd-artifacts/phd-clone-c22379e7-3cd7-4b13-8098-926ecd3d00b7\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3652026-01-29T11:58:34.880Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.835495518Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3662026-01-29T11:58:34.880Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.835545899Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3672026-01-29T11:58:34.880Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.835590289Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/088bb567bfaa3a7882ea2569cd9d83b22d77e1f0a4a522e66ac8616f0678446d/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3682026-01-29T11:58:34.880Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.835641691Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/088bb567bfaa3a7882ea2569cd9d83b22d77e1f0a4a522e66ac8616f0678446d/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"}
3692026-01-29T11:58:34.880Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.835687542Z","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"}
3702026-01-29T11:58:34.904Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 879","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.85320821Z","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"}
3712026-01-29T11:58:34.904Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.853455615Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":17,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3722026-01-29T11:58:34.904Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.853541747Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3732026-01-29T11:58:34.904Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:34.8541688Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3742026-01-29T11:58:35.310Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.268630013Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3752026-01-29T11:58:35.334Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.269723536Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df, name: \"phd-vm-c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0e033a25-b95a-4809-954b-0b90d31076ea, project_id: c96d1e60-1b65-438a-a2e7-7ecf4a0ed9a3, sled_id: bb9da238-93e8-430f-9c5e-4bbbeff8d446, sled_serial: \"bb9da238-93e8-430f-9c5e-4bbbeff8d446\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-01-29T11:58:35.334Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.269853278Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-01-29T11:58:35.335Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.269899149Z","target":"phd_framework::test_vm","line":472,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-01-29T11:58:35.335Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.270628134Z","target":"phd_framework::test_vm","line":467,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-01-29T11:58:35.335Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.270698486Z","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"}
3802026-01-29T11:58:35.335Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.270754227Z","target":"phd_framework::test_vm","line":731,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","timeout_duration":"300s","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3812026-01-29T11:58:35.335Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.270813038Z","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"}
3822026-01-29T11:58:35.335Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.270860309Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-01-29T11:58:35.335Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:35.27090771Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-01-29T11:58:39.651Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.609829753Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4338,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-01-29T11:58:39.651Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.609915005Z","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"}
3862026-01-29T11:58:39.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.610100159Z","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"}
3872026-01-29T11:58:39.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.61015363Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3882026-01-29T11:58:39.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.610191681Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3892026-01-29T11:58:39.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.627947144Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":17,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3902026-01-29T11:58:39.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.628090707Z","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"}
3912026-01-29T11:58:39.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.628427274Z","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"}
3922026-01-29T11:58:39.676Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.628533236Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3932026-01-29T11:58:39.676Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.628618828Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3942026-01-29T11:58:39.702Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.661005771Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3952026-01-29T11:58:39.702Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.661070482Z","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"}
3962026-01-29T11:58:39.702Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.661112653Z","target":"phd_framework::test_vm","line":782,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4390,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972026-01-29T11:58:39.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.661246176Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3982026-01-29T11:58:39.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.661304927Z","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)","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3992026-01-29T11:58:39.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.671512846Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4002026-01-29T11:58:39.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.671678139Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012026-01-29T11:58:39.726Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.671779491Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4022026-01-29T11:58:39.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.694108628Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4032026-01-29T11:58:39.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.694254051Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4042026-01-29T11:58:39.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.694311153Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4052026-01-29T11:58:39.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.704735596Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4062026-01-29T11:58:39.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.705021562Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4072026-01-29T11:58:39.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.705119734Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4082026-01-29T11:58:39.779Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.737597499Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4092026-01-29T11:58:39.803Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.737877344Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4102026-01-29T11:58:39.803Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.737970006Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4112026-01-29T11:58:39.803Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.749228797Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4122026-01-29T11:58:39.803Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.749439481Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4132026-01-29T11:58:39.803Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.749526053Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4142026-01-29T11:58:39.827Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.771970962Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4152026-01-29T11:58:39.827Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.772094785Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4162026-01-29T11:58:39.827Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.772211927Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4172026-01-29T11:58:39.827Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.772292189Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-01-29T11:58:39.827Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.772396541Z","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"}
4192026-01-29T11:58:39.827Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.772482693Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4202026-01-29T11:58:39.827Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.772579704Z","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"}
4212026-01-29T11:58:39.851Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 880","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.790765697Z","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"}
4222026-01-29T11:58:39.851Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.791003632Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4232026-01-29T11:58:39.851Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.791087954Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","target":"migration_from_base_and_back_lifecycle_0"}
4242026-01-29T11:58:39.851Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.791154605Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"39b95d95-e14b-440e-b80c-4a5483947236","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","target":"migration_from_base_and_back_lifecycle_0"}
4252026-01-29T11:58:39.851Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.791243727Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_0"}
4262026-01-29T11:58:39.851Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:39.791800948Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_0"}
4272026-01-29T11:58:40.562Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:40.520731469Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 2c0c3f4c-29ba-488c-8fef-ad9c8be425ef, name: \"phd-vm-2c0c3f4c-29ba-488c-8fef-ad9c8be425ef\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0e033a25-b95a-4809-954b-0b90d31076ea, project_id: c96d1e60-1b65-438a-a2e7-7ecf4a0ed9a3, sled_id: bf16c175-2211-4dd3-aa3c-e194ac994beb, sled_serial: \"bf16c175-2211-4dd3-aa3c-e194ac994beb\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_0"}
4282026-01-29T11:58:40.562Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:40.520891762Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","migration_id":"39b95d95-e14b-440e-b80c-4a5483947236","source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","target":"migration_from_base_and_back_lifecycle_0"}
4292026-01-29T11:58:42.821Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:42.780112206Z","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}}"}
4302026-01-29T11:58:43.431Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:43.389845997Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","target":"migration_from_base_and_back_lifecycle_0"}
4312026-01-29T11:58:43.431Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:43.389919118Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","migration_id":"39b95d95-e14b-440e-b80c-4a5483947236","source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","elapsed_milliseconds":2868,"target":"migration_from_base_and_back_lifecycle_0"}
4322026-01-29T11:58:43.455Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:43.391791496Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4332026-01-29T11:58:43.455Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:43.392053592Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4342026-01-29T11:58:43.455Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:43.392110403Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4352026-01-29T11:58:43.455Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:43.392925989Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base_and_back","vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4362026-01-29T11:58:43.513Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:43.471405056Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":79,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4372026-01-29T11:58:43.513Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:43.471542389Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":8617,"vm_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4382026-01-29T11:58:46.083Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.042095605Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":2649,"vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4392026-01-29T11:58:46.107Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.042256108Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4402026-01-29T11:58:46.108Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.04231531Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4412026-01-29T11:58:46.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.075239084Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4422026-01-29T11:58:46.132Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.075356926Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__BASE_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4432026-01-29T11:58:46.132Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.075475918Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4442026-01-29T11:58:46.132Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.07557494Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_1","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"}
4452026-01-29T11:58:46.132Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.075694523Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/088bb567bfaa3a7882ea2569cd9d83b22d77e1f0a4a522e66ac8616f0678446d/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4462026-01-29T11:58:46.132Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.075786905Z","target":"phd_framework::test_vm::server","line":64,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/ff12d5cb021e34447b44301f70434e861b07d2779c16abe2f2efef49ff02fffb/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9004","server_path":"\"/phd-artifacts/088bb567bfaa3a7882ea2569cd9d83b22d77e1f0a4a522e66ac8616f0678446d/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4472026-01-29T11:58:46.132Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.075874017Z","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"}
4482026-01-29T11:58:46.156Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 882","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.095286274Z","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"}
4492026-01-29T11:58:46.156Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.095634801Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":20,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-01-29T11:58:46.156Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.095773624Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","target":"migration_from_base_and_back_lifecycle_1"}
4512026-01-29T11:58:46.156Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.095883946Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"f53a5b9f-7fdc-4926-8ec7-f0d84e4bf69c","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","target":"migration_from_base_and_back_lifecycle_1"}
4522026-01-29T11:58:46.156Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.095961058Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_1"}
4532026-01-29T11:58:46.156Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.096428367Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_1"}
4542026-01-29T11:58:46.620Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.57872281Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 0c936bde-24fd-424c-a6f0-1fb765965aed, name: \"phd-vm-0c936bde-24fd-424c-a6f0-1fb765965aed\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0e033a25-b95a-4809-954b-0b90d31076ea, project_id: c96d1e60-1b65-438a-a2e7-7ecf4a0ed9a3, sled_id: 2543652b-fbc5-4533-9a4a-7590c8f8ad68, sled_serial: \"2543652b-fbc5-4533-9a4a-7590c8f8ad68\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_1"}
4552026-01-29T11:58:46.620Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:46.578846912Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","migration_id":"f53a5b9f-7fdc-4926-8ec7-f0d84e4bf69c","source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","target":"migration_from_base_and_back_lifecycle_1"}
4562026-01-29T11:58:48.875Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:48.834263939Z","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}}"}
4572026-01-29T11:58:49.528Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.486591981Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","target":"migration_from_base_and_back_lifecycle_1"}
4582026-01-29T11:58:49.528Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.486646872Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","migration_id":"f53a5b9f-7fdc-4926-8ec7-f0d84e4bf69c","source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","elapsed_milliseconds":2907,"target":"migration_from_base_and_back_lifecycle_1"}
4592026-01-29T11:58:49.552Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.488710954Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4602026-01-29T11:58:49.552Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.488931039Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4612026-01-29T11:58:49.552Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.48898879Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4622026-01-29T11:58:49.552Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.490008091Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4632026-01-29T11:58:49.610Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.569198462Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":80,"vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4642026-01-29T11:58:49.610Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.569361535Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":9778,"vm_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","vm":"migration_from_base_and_back_lifecycle_0","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4652026-01-29T11:58:49.611Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.569447077Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back","target_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","elapsed_milliseconds":9778,"source_id":"c531f6e8-bf47-48e4-9c5c-bf5c8a38a3df","target":"migration_from_base_and_back_lifecycle_0"}
4662026-01-29T11:58:49.924Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.882557006Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":393,"vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4672026-01-29T11:58:49.948Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.882838772Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4682026-01-29T11:58:49.948Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.882958264Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4692026-01-29T11:58:49.972Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.915915039Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4702026-01-29T11:58:49.972Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.916063142Z","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"}
4712026-01-29T11:58:49.972Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.916208285Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4722026-01-29T11:58:49.972Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.916299827Z","target":"phd_framework::test_vm","line":217,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4732026-01-29T11:58:49.973Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.916410489Z","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"}
4742026-01-29T11:58:49.973Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.916499871Z","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"}
4752026-01-29T11:58:49.973Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.916580712Z","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"}
4762026-01-29T11:58:49.997Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 884","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.936937629Z","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"}
4772026-01-29T11:58:49.997Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.937228275Z","target":"phd_framework::test_vm","line":199,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":20,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-01-29T11:58:49.997Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.937330617Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","target":"migration_from_base_and_back_lifecycle_2"}
4792026-01-29T11:58:49.997Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.937417229Z","target":"phd_framework::test_vm","line":534,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"a3337380-54a9-4c22-b7fd-87fae9821235","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","target":"migration_from_base_and_back_lifecycle_2"}
4802026-01-29T11:58:49.997Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.937506041Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm":"migration_from_base_and_back_lifecycle_2","target":"migration_from_base_and_back_lifecycle_2"}
4812026-01-29T11:58:49.997Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:49.938120733Z","target":"phd_framework::test_vm","line":347,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm":"migration_from_base_and_back_lifecycle_2","target":"migration_from_base_and_back_lifecycle_2"}
4822026-01-29T11:58:50.299Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:50.258194154Z","target":"phd_framework::test_vm","line":406,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 79101357-063a-4106-a3ce-eb0444e30efd, name: \"phd-vm-79101357-063a-4106-a3ce-eb0444e30efd\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 0e033a25-b95a-4809-954b-0b90d31076ea, project_id: c96d1e60-1b65-438a-a2e7-7ecf4a0ed9a3, sled_id: 58d14054-25c5-4cd2-a126-6c7c2b8536b0, sled_serial: \"58d14054-25c5-4cd2-a126-6c7c2b8536b0\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm":"migration_from_base_and_back_lifecycle_2","target":"migration_from_base_and_back_lifecycle_2"}
4832026-01-29T11:58:50.299Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:50.258319527Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","migration_id":"a3337380-54a9-4c22-b7fd-87fae9821235","source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","target":"migration_from_base_and_back_lifecycle_2"}
4842026-01-29T11:58:52.553Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:52.511831064Z","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}}"}
4852026-01-29T11:58:53.098Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:53.056468102Z","target":"phd_framework::test_vm","line":568,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","target":"migration_from_base_and_back_lifecycle_2"}
4862026-01-29T11:58:53.098Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:53.056528884Z","target":"phd_framework::test_vm","line":555,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","migration_id":"a3337380-54a9-4c22-b7fd-87fae9821235","source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","elapsed_milliseconds":2798,"target":"migration_from_base_and_back_lifecycle_2"}
4872026-01-29T11:58:53.122Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:53.058188978Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4882026-01-29T11:58:53.122Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:53.058425782Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4892026-01-29T11:58:53.122Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:53.058484724Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4902026-01-29T11:58:53.122Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:53.059502524Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4912026-01-29T11:58:53.177Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:53.135942359Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":77,"vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4922026-01-29T11:58:53.177Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:53.136076712Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":7040,"vm_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","vm":"migration_from_base_and_back_lifecycle_1","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4932026-01-29T11:58:53.177Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:53.136135003Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0","target_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","elapsed_milliseconds":7040,"source_id":"2c0c3f4c-29ba-488c-8fef-ad9c8be425ef","target":"migration_from_base_and_back_lifecycle_1"}
4942026-01-29T11:58:54.084Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.042290741Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":983,"vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4952026-01-29T11:58:54.108Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.042524126Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4962026-01-29T11:58:54.108Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.042618008Z","target":"phd_framework::test_vm","line":804,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4972026-01-29T11:58:54.132Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.074687014Z","target":"phd_framework::test_vm","line":797,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4982026-01-29T11:58:54.132Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.074822437Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4992026-01-29T11:58:54.132Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.075071582Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5002026-01-29T11:58:54.132Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.075241745Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
5012026-01-29T11:58:54.132Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.075265676Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":18806}
5022026-01-29T11:58:54.132Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.075398519Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5032026-01-29T11:58:54.132Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.076124204Z","target":"phd_framework::test_vm","line":1077,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5042026-01-29T11:58:54.732Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.690887257Z","target":"phd_framework::test_vm::server","line":140,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5052026-01-29T11:58:54.807Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.765597317Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-01-29T11:58:54.807Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.765691929Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-c22379e7-3cd7-4b13-8098-926ecd3d00b7\"]","verb":"destroy","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5072026-01-29T11:58:54.831Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.784904772Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-01-29T11:58:54.831Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.784949343Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-1f358b74-5043-427f-a44b-c344e0368e9c\"]","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-01-29T11:58:54.855Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.796689243Z","target":"phd_framework::test_vm","line":1054,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":721,"vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5102026-01-29T11:58:54.855Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.796828766Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":721}
5112026-01-29T11:58:54.855Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.796895337Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5122026-01-29T11:58:54.855Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.796926108Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5132026-01-29T11:58:54.855Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 109.50s
5142026-01-29T11:58:54.855Z
5152026-01-29T11:58:54.855Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.796902817Z","target":"phd_framework::test_vm","line":308,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":4859,"vm_id":"79101357-063a-4106-a3ce-eb0444e30efd","source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","vm":"migration_from_base_and_back_lifecycle_2","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5162026-01-29T11:58:54.855Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.796977389Z","target":"phd_framework::test_vm","line":501,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1","target_id":"79101357-063a-4106-a3ce-eb0444e30efd","elapsed_milliseconds":4859,"source_id":"0c936bde-24fd-424c-a6f0-1fb765965aed","target":"migration_from_base_and_back_lifecycle_2"}
5172026-01-29T11:58:54.855Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.79701499Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5182026-01-29T11:58:54.855Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"sock","pid":854,"time":"2026-01-29T11:58:54.79703761Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":19997,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5192026-01-29T11:58:54.907Z
5202026-01-29T11:58:54.931Zreal 1:50.249440416
5212026-01-29T11:58:54.931Zuser 37.384248444
5222026-01-29T11:58:54.931Zsys 15.743329951
5232026-01-29T11:58:54.931Ztrap 0.007735962
5242026-01-29T11:58:54.931Ztflt 0.001486826
5252026-01-29T11:58:54.931Zdflt 0.000634608
5262026-01-29T11:58:54.931Zkflt 0.000000000
5272026-01-29T11:58:54.931Zlock 1:46:26.285450770
5282026-01-29T11:58:54.931Zslp 4:14.032267431
5292026-01-29T11:58:54.931Zlat 0.928368430
5302026-01-29T11:58:54.931Zstop 8.236157589
5312026-01-29T11:58:54.931Z+ failcount=0
5322026-01-29T11:58:54.931Z+ set -e
5332026-01-29T11:58:54.931Z+ 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
5342026-01-29T11:58:54.931ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5352026-01-29T11:58:54.931Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5362026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log 232K
5372026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5382026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log 233K
5392026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5402026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log 145K
5412026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_and_back.serial.log 7K
5422026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_and_back.stderr.log 0K
5432026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_and_back.stdout.log 139K
5442026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log 0K
5452026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log 145K
5462026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base.serial.log 7K
5472026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base.stderr.log 0K
5482026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_from_base.stdout.log 138K
5492026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log 0K
5502026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log 145K
5512026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_serial_history_base.serial.log 7K
5522026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_serial_history_base.stderr.log 0K
5532026-01-29T11:58:54.932Za /tmp/propolis-phd/migration_serial_history_base.stdout.log 138K
5542026-01-29T11:58:54.932Z+ exitcode=0
5552026-01-29T11:58:54.932Z+ '[' 0 -eq 0 ']'
5562026-01-29T11:58:54.932Z+ echo
5572026-01-29T11:58:54.932Z
5582026-01-29T11:58:54.932Z+ echo 'ALL TESTS PASSED'
5592026-01-29T11:58:54.932ZALL TESTS PASSED
5602026-01-29T11:58:54.932Z+ echo
5612026-01-29T11:58:54.932Z
5622026-01-29T11:58:54.932Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5632026-01-29T11:58:54.932Z+ read
5642026-01-29T11:58:54.932Z+ exit 0
5652026-01-29T11:58:54.932Zprocess exited: duration 123755 ms, exit code 0
 
5662026-01-29T11:58:54.981Zfound 2 output files
5672026-01-29T11:58:54.981Zuploading: /tmp/phd-runner.log (162802 bytes)
5682026-01-29T11:58:56.145Zuploaded: /tmp/phd-runner.log
5692026-01-29T11:58:56.145Zuploading: /tmp/phd-tmp-files.tar.gz (104591 bytes)
5702026-01-29T11:58:57.348Zuploaded: /tmp/phd-tmp-files.tar.gz