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

Buildomat Job: 01M401KA14ZQVQ1E7D63M7ANNG

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-10-03T05:02:11.678Zjob dependencies complete; ready to run (waiting for 11 m 27 s)
22026-10-03T05:48:01.380Zjob assigned to worker 01M404P5TVYHW33YWRCRMF4V68 [factory edgar, gimlet/BRM42220010/1686] (queued for 45 m 49 s)
32026-10-03T05:48:02.445Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-10-03T05:48:02.501Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-10-03T05:48:02.501Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-10-03T05:48:02.540Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-10-03T05:48:02.540Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-10-03T05:48:10.533Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-10-03T05:48:10.533Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-10-03T05:48:10.571Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-10-03T05:48:10.571Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-10-03T05:48:22.726Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-10-03T05:48:22.726Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-10-03T05:48:35.560Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-10-03T05:48:35.560Zstarting task 0: "setup"
162026-10-03T05:48:35.584Z++ uname -s
172026-10-03T05:48:35.584Z+ kern=SunOS
182026-10-03T05:48:35.584Z+ build_user=build
192026-10-03T05:48:35.584Z+ build_uid=12345
202026-10-03T05:48:35.584Z+ work_dir=/work
212026-10-03T05:48:35.584Z+ input_dir=/input
222026-10-03T05:48:35.584Z+ [[ 0 == 12345 ]]
232026-10-03T05:48:35.584Z+ case "$kern" in
242026-10-03T05:48:35.584Z+ groupadd -g 12345 build
252026-10-03T05:48:35.607Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-10-03T05:48:37.595Z+ zfs create -o mountpoint=/work rpool/work
272026-10-03T05:48:37.633Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-10-03T05:48:37.656Z+ home_fs=
292026-10-03T05:48:37.657Z+ [[ '' == autofs ]]
302026-10-03T05:48:37.657Z+ mkdir -p /home/build
312026-10-03T05:48:37.657Z+ chown build:build /home/build /work
322026-10-03T05:48:39.647Z+ chmod 0700 /home/build /work
332026-10-03T05:48:39.670Zprocess exited: duration 4092 ms, exit code 0
 
342026-10-03T05:48:39.716Zstarting task 1: "authentication"
352026-10-03T05:48:39.785Zprocess exited: duration 68 ms, exit code 0
 
362026-10-03T05:48:39.830Zstarting task 2: "build"
372026-10-03T05:48:39.856Z+ indir=/input
382026-10-03T05:48:39.856Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-10-03T05:48:39.856Z+ phddir=/work/phd-test
402026-10-03T05:48:39.856Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-10-03T05:48:39.879Z++ pilot local disk list -H -o type,disk
422026-10-03T05:48:39.879Z++ grep -v M.2
432026-10-03T05:48:39.879Z++ cut -f 2
442026-10-03T05:48:39.930Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
452026-10-03T05:48:42.478Z+ artifactdir=/phd-artifacts
462026-10-03T05:48:42.478Z+ banner Inputs
472026-10-03T05:48:42.501Z ###
482026-10-03T05:48:42.501Z # # # ##### # # ##### ####
492026-10-03T05:48:42.501Z # ## # # # # # # #
502026-10-03T05:48:42.501Z # # # # # # # # # ####
512026-10-03T05:48:42.502Z # # # # ##### # # # #
522026-10-03T05:48:42.502Z # # ## # # # # # #
532026-10-03T05:48:42.502Z ### # # # #### # ####
542026-10-03T05:48:42.502Z
552026-10-03T05:48:42.502Z+ find /input -ls
562026-10-03T05:48:42.502Z 34 1 drwxr-xr-x 3 root root 3 Oct 3 05:48 /input
572026-10-03T05:48:42.502Z 2 1 drwxr-xr-x 3 root root 3 Oct 3 05:48 /input/phd-build
582026-10-03T05:48:42.502Z 3 2 drwxr-xr-x 2 root root 8 Oct 3 05:48 /input/phd-build/out
592026-10-03T05:48:42.502Z 256 1 -rw-r--r-- 1 root root 65 Oct 3 05:48 /input/phd-build/out/propolis-server-debug.sha256.txt
602026-10-03T05:48:42.502Z 130 187919 -rw-r--r-- 1 root root 192330629 Oct 3 05:48 /input/phd-build/out/phd-runner.tar.gz
612026-10-03T05:48:42.502Z 129 1 -rw-r--r-- 1 root root 65 Oct 3 05:48 /input/phd-build/out/phd-runner.sha256.txt
622026-10-03T05:48:42.502Z 512 223294 -rw-r--r-- 1 root root 228596008 Oct 3 05:48 /input/phd-build/out/propolis-tests-debug.tar.gz
632026-10-03T05:48:42.502Z 128 2 -rw-r--r-- 1 root root 2573 Oct 3 05:48 /input/phd-build/out/phd-run-with-args.sh
642026-10-03T05:48:42.502Z 384 261786 -rw-r--r-- 1 root root 268032670 Oct 3 05:48 /input/phd-build/out/propolis-server-debug.tar.gz
652026-10-03T05:48:42.502Z+ rm -rf /work/phd-test
662026-10-03T05:48:42.502Z+ mkdir /work/phd-test
672026-10-03T05:48:42.502Z+ for p in $indir/$indir_suffix
682026-10-03T05:48:42.502Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-10-03T05:48:57.634ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-10-03T05:48:57.634Zx phd-runner, 737147232 bytes, 1439741 tape blocks
712026-10-03T05:48:57.634Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-10-03T05:48:57.657Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-10-03T05:49:02.089Z+ for f in $(tar tf "$p")
742026-10-03T05:49:02.089Z+ chmod +x /work/phd-test/phd-runner
752026-10-03T05:49:02.112Z+ for f in $(tar tf "$p")
762026-10-03T05:49:02.112Z+ chmod +x /work/phd-test/artifacts.toml
772026-10-03T05:49:02.112Z+ for p in $indir/$indir_suffix
782026-10-03T05:49:02.112Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-10-03T05:49:20.880ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-10-03T05:49:20.881Zx propolis-server, 1074454824 bytes, 2098545 tape blocks
812026-10-03T05:49:20.903Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-10-03T05:49:27.740Z+ for f in $(tar tf "$p")
832026-10-03T05:49:27.740Z+ chmod +x /work/phd-test/propolis-server
842026-10-03T05:49:27.763Z+ for p in $indir/$indir_suffix
852026-10-03T05:49:27.763Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-10-03T05:49:44.561ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-10-03T05:49:44.562Zx target/debug/deps/propolis-16accc46ec7fe886, 916123496 bytes, 1789304 tape blocks
882026-10-03T05:49:44.585Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-10-03T05:49:50.252Z+ for f in $(tar tf "$p")
902026-10-03T05:49:50.252Z+ chmod +x /work/phd-test/target/debug/deps/propolis-16accc46ec7fe886
912026-10-03T05:49:50.275Z+ ls /work/phd-test
922026-10-03T05:49:50.275Zartifacts.toml
932026-10-03T05:49:50.275Zphd-runner
942026-10-03T05:49:50.275Zpropolis-server
952026-10-03T05:49:50.275Ztarget
962026-10-03T05:49:50.275Z+ banner Setup
972026-10-03T05:49:50.275Z #####
982026-10-03T05:49:50.275Z# # ###### ##### # # #####
992026-10-03T05:49:50.275Z# # # # # # #
1002026-10-03T05:49:50.275Z ##### ##### # # # # #
1012026-10-03T05:49:50.275Z # # # # # #####
1022026-10-03T05:49:50.275Z# # # # # # #
1032026-10-03T05:49:50.275Z ##### ###### # #### #
1042026-10-03T05:49:50.275Z
1052026-10-03T05:49:50.276Z+ tmpdir=/tmp/propolis-phd
1062026-10-03T05:49:50.276Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-10-03T05:49:50.276Z+ mkdir /tmp/propolis-phd
1082026-10-03T05:49:50.276Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-10-03T05:49:50.739Z+ banner Tests
1102026-10-03T05:49:50.763Z#######
1112026-10-03T05:49:50.763Z # ###### #### ##### ####
1122026-10-03T05:49:50.763Z # # # # #
1132026-10-03T05:49:50.763Z # ##### #### # ####
1142026-10-03T05:49:50.763Z # # # # #
1152026-10-03T05:49:50.763Z # # # # # # #
1162026-10-03T05:49:50.763Z # ###### #### # ####
1172026-10-03T05:49:50.763Z
1182026-10-03T05:49:50.763Z+ runner=/work/phd-test/phd-runner
1192026-10-03T05:49:50.763Z+ artifacts=/work/phd-test/artifacts.toml
1202026-10-03T05:49:50.763Z+ propolis=/work/phd-test/propolis-server
1212026-10-03T05:49:50.763Z+ ls /work/phd-test/phd-runner
1222026-10-03T05:49:50.763Z/work/phd-test/phd-runner
1232026-10-03T05:49:50.763Z+ ls /work/phd-test/artifacts.toml
1242026-10-03T05:49:50.763Z/work/phd-test/artifacts.toml
1252026-10-03T05:49:50.764Z+ ls /work/phd-test/propolis-server
1262026-10-03T05:49:50.764Z/work/phd-test/propolis-server
1272026-10-03T05:49:50.764Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-10-03T05:49:50.764Z+ set +e
1292026-10-03T05:49:50.764Z+ RUST_BACKTRACE=1
1302026-10-03T05:49:50.764Z+ RUST_LOG=info,phd=debug
1312026-10-03T05:49:50.764Z+ 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
1322026-10-03T05:49:50.764Z+ tee /tmp/phd-runner.log
1332026-10-03T05:49:50.957Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:50.93898739Z","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, manual_stop_on_failure: false }), disable_ansi: false, emit_bunyan: true }"}
1342026-10-03T05:49:50.980Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:50.966381983Z","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(\"bf64f45b1a58e69d126a3c6ca1e4512c88668132\"), sha256: \"740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448\" }), 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: 254, tv_nsec: 898525394 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-10-03T05:49:50.980Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:50.966978701Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-10-03T05:49:50.980Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:50.968014447Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"ad8a31742adc45e925e63443a5b43c8e30604022"}
1372026-10-03T05:49:51.004Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:50.973991298Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/ad8a31742adc45e925e63443a5b43c8e30604022/crucible-nightly.sha256.txt","timeout":"600s"}
1382026-10-03T05:49:53.210Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.201786321Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-10-03T05:49:53.810Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.801805945Z","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/cef309aad286c420de79cef93b734d7e73b341f0/propolis-server.sha256.txt"}
1402026-10-03T05:49:53.969Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.960769118Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-10-03T05:49:53.992Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.961599321Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-10-03T05:49:53.992Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.963453027Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-10-03T05:49:53.992Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.964051589Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-10-03T05:49:53.992Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.964088199Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-10-03T05:49:53.992Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.964123196Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-10-03T05:49:53.992Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.965322764Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
1472026-10-03T05:49:53.992Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.966506912Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
1482026-10-03T05:49:53.992Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:53.968095623Z","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/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
1492026-10-03T05:49:54.461Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:54.452671945Z","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::serial_history"}
1502026-10-03T05:49:54.484Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:49:54.466308026Z","target":"phd_framework::artifacts::store","line":614,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::serial_history"}
1512026-10-03T05:50:01.155Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.146181357Z","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"}
1522026-10-03T05:50:01.155Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.146323578Z","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"}
1532026-10-03T05:50:01.178Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.16262334Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 3.52M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
1542026-10-03T05:50:01.178Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.164031756Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-c578fed4-f802-4444-8fae-adb2e1d58a75\"]","path":"phd_tests::migrate::from_base::serial_history"}
1552026-10-03T05:50:01.202Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.187011648Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-c578fed4-f802-4444-8fae-adb2e1d58a75\", \"phd-artifacts/phd-clone-f18a6245-9d12-4228-84c6-c41f547d04ac\"]","path":"phd_tests::migrate::from_base::serial_history"}
1562026-10-03T05:50:01.226Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.20432314Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-f18a6245-9d12-4228-84c6-c41f547d04ac\"]","path":"phd_tests::migrate::from_base::serial_history"}
1572026-10-03T05:50:01.226Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.214911094Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-f18a6245-9d12-4228-84c6-c41f547d04ac 0B 25.3T 49.0M /phd-artifacts/phd-clone-f18a6245-9d12-4228-84c6-c41f547d04ac\n","path":"phd_tests::migrate::from_base::serial_history"}
1582026-10-03T05:50:01.249Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.218863754Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1592026-10-03T05:50:01.249Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.219471954Z","target":"phd_framework::test_vm","line":318,"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"}
1602026-10-03T05:50:01.249Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.21954308Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/307d7cf409a11795bd2f449aff90849e1cd9fd6e26ea2c6267e3110786362da9/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1612026-10-03T05:50:01.250Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:01.219616901Z","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/cef309aad286c420de79cef93b734d7e73b341f0/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1622026-10-03T05:50:17.092Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:17.082594946Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/307d7cf409a11795bd2f449aff90849e1cd9fd6e26ea2c6267e3110786362da9/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
1632026-10-03T05:50:17.092Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:17.082681932Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::serial_history"}
1642026-10-03T05:50:41.885Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:41.875122408Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/307d7cf409a11795bd2f449aff90849e1cd9fd6e26ea2c6267e3110786362da9/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
1652026-10-03T05:50:41.885Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:41.875245173Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
1662026-10-03T05:50:42.002Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 917","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:41.992125226Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
1672026-10-03T05:50:42.025Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.008238342Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1682026-10-03T05:50:42.048Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.020773442Z","target":"phd_framework::test_vm","line":455,"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":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1692026-10-03T05:50:42.048Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.024654956Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":40805}
1702026-10-03T05:50:42.528Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.51853335Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-10-03T05:50:42.554Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.525358168Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 713e6e50-517b-4c19-810d-53a9972e98a9, name: \"phd-vm-713e6e50-517b-4c19-810d-53a9972e98a9\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 1fef43db-a9ba-4f7e-ae4b-5d2eeef1e389, project_id: 5eedf955-1f10-4ae1-8a22-67de709fcccd, sled_id: 758bd4f8-9e24-4ed5-981c-3208c0ec2691, sled_serial: \"758bd4f8-9e24-4ed5-981c-3208c0ec2691\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1722026-10-03T05:50:42.554Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.52551127Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1732026-10-03T05:50:42.554Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.52556884Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1742026-10-03T05:50:42.554Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.528220157Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":2}
1752026-10-03T05:50:42.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.528382487Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1762026-10-03T05:50:42.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.528466998Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1772026-10-03T05:50:42.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.528523265Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
1782026-10-03T05:50:42.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.528601725Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1792026-10-03T05:50:42.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:42.528659485Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1802026-10-03T05:50:47.092Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.082004656Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":4553}
1812026-10-03T05:50:47.092Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.082099617Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
1822026-10-03T05:50:47.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.086257708Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1832026-10-03T05:50:47.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.086315118Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1842026-10-03T05:50:47.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.086356908Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1852026-10-03T05:50:47.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.112199861Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":25}
1862026-10-03T05:50:47.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.112356219Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
1872026-10-03T05:50:47.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.112766882Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1882026-10-03T05:50:47.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.112875229Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1892026-10-03T05:50:47.138Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.112961424Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1902026-10-03T05:50:47.161Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.145719629Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":32}
1912026-10-03T05:50:47.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.145811455Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1922026-10-03T05:50:47.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.145869946Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4617}
1932026-10-03T05:50:47.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.146078965Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1942026-10-03T05:50:47.162Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.146816912Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1952026-10-03T05:50:47.185Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.156825103Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":10}
1962026-10-03T05:50:47.185Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.157006539Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1972026-10-03T05:50:47.185Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.157082815Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1982026-10-03T05:50:47.208Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.190122365Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":33}
1992026-10-03T05:50:47.208Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.190326645Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2002026-10-03T05:50:47.208Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.190404574Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2012026-10-03T05:50:47.231Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.201126696Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":10}
2022026-10-03T05:50:47.231Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.201436998Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2032026-10-03T05:50:47.231Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.201547659Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2042026-10-03T05:50:47.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.23432985Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":32}
2052026-10-03T05:50:47.257Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.244929269Z","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"}
2062026-10-03T05:50:47.257Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.245056151Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2072026-10-03T05:50:47.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.245109132Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
2082026-10-03T05:50:47.280Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.245604637Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","sha256":"None","path":"phd_tests::migrate::from_base::serial_history"}
2092026-10-03T05:50:47.280Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.245689579Z","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::serial_history"}
2102026-10-03T05:50:47.280Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.245757859Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history"}
2112026-10-03T05:50:47.280Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.245835878Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2122026-10-03T05:50:47.303Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 918","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.290793753Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
2132026-10-03T05:50:47.326Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.303537571Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":58}
2142026-10-03T05:50:47.326Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.303634446Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","target":"migration_serial_history_base_lifecycle_0"}
2152026-10-03T05:50:47.326Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.304111687Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"782227ce-6ca0-4d1d-a177-b28e2ce6e832","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","target":"migration_serial_history_base_lifecycle_0"}
2162026-10-03T05:50:47.326Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.304184806Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","vm":"migration_serial_history_base_lifecycle_0","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","target":"migration_serial_history_base_lifecycle_0"}
2172026-10-03T05:50:47.326Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.304740536Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","vm":"migration_serial_history_base_lifecycle_0","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","target":"migration_serial_history_base_lifecycle_0"}
2182026-10-03T05:50:47.975Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.965508576Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 37448c04-beca-47c1-91c7-5eb07bb65fd1, name: \"phd-vm-37448c04-beca-47c1-91c7-5eb07bb65fd1\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 1fef43db-a9ba-4f7e-ae4b-5d2eeef1e389, project_id: 5eedf955-1f10-4ae1-8a22-67de709fcccd, sled_id: aacd1c80-4c7c-4817-bc21-303402e830b2, sled_serial: \"aacd1c80-4c7c-4817-bc21-303402e830b2\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","vm":"migration_serial_history_base_lifecycle_0","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","target":"migration_serial_history_base_lifecycle_0"}
2192026-10-03T05:50:47.998Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:47.96667449Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","migration_id":"782227ce-6ca0-4d1d-a177-b28e2ce6e832","target":"migration_serial_history_base_lifecycle_0"}
2202026-10-03T05:50:50.452Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.443053643Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7756}}"}
2212026-10-03T05:50:50.939Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.929945021Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","target":"migration_serial_history_base_lifecycle_0"}
2222026-10-03T05:50:50.940Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.930050732Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","migration_id":"782227ce-6ca0-4d1d-a177-b28e2ce6e832","elapsed_milliseconds":2963,"target":"migration_serial_history_base_lifecycle_0"}
2232026-10-03T05:50:50.963Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.932903264Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2242026-10-03T05:50:50.963Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.937790436Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2252026-10-03T05:50:50.963Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.942047316Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2262026-10-03T05:50:50.963Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.942761207Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2272026-10-03T05:50:50.963Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.944322255Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2282026-10-03T05:50:50.963Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.944399903Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8425}
2292026-10-03T05:50:50.963Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.945084499Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2302026-10-03T05:50:50.963Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:50.945159833Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2312026-10-03T05:50:51.022Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.012627575Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":76}
2322026-10-03T05:50:51.045Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.012925263Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"713e6e50-517b-4c19-810d-53a9972e98a9","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","elapsed_milliseconds":9004}
2332026-10-03T05:50:51.388Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.377842258Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2342026-10-03T05:50:51.491Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.481296644Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2352026-10-03T05:50:51.491Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.481391505Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-f18a6245-9d12-4228-84c6-c41f547d04ac\"]","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2362026-10-03T05:50:51.519Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.509274742Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2372026-10-03T05:50:51.519Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.509372839Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-c578fed4-f802-4444-8fae-adb2e1d58a75\"]","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2382026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.528644918Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":586}
2392026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.528906948Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","target":"migration_serial_history_base_lifecycle_0","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","elapsed_milliseconds":4224,"source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1"}
2402026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.529099645Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","source_id":"713e6e50-517b-4c19-810d-53a9972e98a9","target_id":"37448c04-beca-47c1-91c7-5eb07bb65fd1","elapsed_milliseconds":4225,"target":"migration_serial_history_base_lifecycle_0"}
2412026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.529169148Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":57562}
2422026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.529480021Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":584}
2432026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.529573479Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2442026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.529619577Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2452026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.529660866Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2462026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.529817815Z","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"}
2472026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.529929859Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2482026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.530004231Z","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"}
2492026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.530073002Z","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"}
2502026-10-03T05:50:51.542Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.530152103Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2512026-10-03T05:50:51.565Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.54097632Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2522026-10-03T05:50:51.566Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.541083044Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-74355da4-0179-48e8-a622-24b3b35942ae\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-10-03T05:50:51.588Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.558534432Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-74355da4-0179-48e8-a622-24b3b35942ae\", \"phd-artifacts/phd-clone-03dd6d43-8273-4599-8570-a27dc2769969\"]","verb":"clone","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-10-03T05:50:51.589Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.576225317Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-03dd6d43-8273-4599-8570-a27dc2769969\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-10-03T05:50:51.612Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.58644442Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-03dd6d43-8273-4599-8570-a27dc2769969 0B 25.3T 1.30G /phd-artifacts/phd-clone-03dd6d43-8273-4599-8570-a27dc2769969\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-10-03T05:50:51.612Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.587094209Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2572026-10-03T05:50:51.612Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.587163912Z","target":"phd_framework::test_vm","line":318,"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"}
2582026-10-03T05:50:51.612Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.587241941Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/307d7cf409a11795bd2f449aff90849e1cd9fd6e26ea2c6267e3110786362da9/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2592026-10-03T05:50:51.612Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.587308719Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/307d7cf409a11795bd2f449aff90849e1cd9fd6e26ea2c6267e3110786362da9/propolis-server\"","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2602026-10-03T05:50:51.612Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.587385134Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2612026-10-03T05:50:51.638Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 927","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.628821141Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2622026-10-03T05:50:51.661Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.643063819Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":55}
2632026-10-03T05:50:51.661Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.643197734Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2642026-10-03T05:50:51.661Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:51.643893381Z","target":"phd_framework::test_vm","line":455,"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":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2652026-10-03T05:50:52.432Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.42284874Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2662026-10-03T05:50:52.475Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.424252879Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: b9a9cb14-a826-4c81-a906-93062c424b36, name: \"phd-vm-b9a9cb14-a826-4c81-a906-93062c424b36\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 48406fbc-45a9-4645-94d3-41b019078bc5, project_id: c2c4032e-763f-4ccc-b741-993b02fc7cdb, sled_id: 3992463f-6843-4192-ae88-44ea0b400d7b, sled_serial: \"3992463f-6843-4192-ae88-44ea0b400d7b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2672026-10-03T05:50:52.475Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.424476926Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2682026-10-03T05:50:52.476Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.424535748Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2692026-10-03T05:50:52.476Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.425767057Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":1}
2702026-10-03T05:50:52.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.425849324Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2712026-10-03T05:50:52.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.425908507Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","vm":"migration_from_base","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-10-03T05:50:52.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.425958372Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2732026-10-03T05:50:52.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.42600446Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2742026-10-03T05:50:52.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:52.426055878Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2752026-10-03T05:50:56.988Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.977953565Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":4551}
2762026-10-03T05:50:56.988Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.97804557Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2772026-10-03T05:50:57.033Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.978241644Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2782026-10-03T05:50:57.033Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.978309594Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2792026-10-03T05:50:57.033Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.97837045Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2802026-10-03T05:50:57.033Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.996516042Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":18}
2812026-10-03T05:50:57.033Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.996680727Z","target":"phd_framework::test_vm","line":847,"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"}
2822026-10-03T05:50:57.033Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.996927778Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2832026-10-03T05:50:57.033Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.996985859Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2842026-10-03T05:50:57.033Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:56.997030965Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2852026-10-03T05:50:57.057Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.029879612Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32}
2862026-10-03T05:50:57.057Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.030028396Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2872026-10-03T05:50:57.057Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.030107447Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4604}
2882026-10-03T05:50:57.057Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.030403832Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2892026-10-03T05:50:57.057Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.030510816Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2902026-10-03T05:50:57.057Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.041154369Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":10}
2912026-10-03T05:50:57.057Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.04134908Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2922026-10-03T05:50:57.057Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.041424865Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2932026-10-03T05:50:57.084Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.073920748Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32}
2942026-10-03T05:50:57.107Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.074937458Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2952026-10-03T05:50:57.107Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.075041887Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2962026-10-03T05:50:57.107Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.084637481Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":9}
2972026-10-03T05:50:57.107Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.084885554Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2982026-10-03T05:50:57.107Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.084987358Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2992026-10-03T05:50:57.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.106835703Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":21}
3002026-10-03T05:50:57.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.107084237Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3012026-10-03T05:50:57.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.107188206Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3022026-10-03T05:50:57.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.117739582Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":10}
3032026-10-03T05:50:57.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.11798485Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3042026-10-03T05:50:57.131Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.118087787Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3052026-10-03T05:50:57.161Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.151174297Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":33}
3062026-10-03T05:50:57.161Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.15141687Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3072026-10-03T05:50:57.161Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.151538101Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3082026-10-03T05:50:57.185Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.162675635Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":11}
3092026-10-03T05:50:57.185Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.162958725Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3102026-10-03T05:50:57.185Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.163066531Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3112026-10-03T05:50:57.208Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.195641077Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32}
3122026-10-03T05:50:57.209Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.195886034Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3132026-10-03T05:50:57.209Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.195989161Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3142026-10-03T05:50:57.232Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.20675811Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":10}
3152026-10-03T05:50:57.232Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.206998158Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3162026-10-03T05:50:57.232Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.207100493Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3172026-10-03T05:50:57.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.239881833Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32}
3182026-10-03T05:50:57.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.241020055Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3192026-10-03T05:50:57.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.241093996Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3202026-10-03T05:50:57.279Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.250979783Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":9}
3212026-10-03T05:50:57.279Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.251304923Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3222026-10-03T05:50:57.279Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.251416596Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3232026-10-03T05:50:57.303Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.283644889Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32}
3242026-10-03T05:50:57.303Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.283885738Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3252026-10-03T05:50:57.303Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.284040734Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3262026-10-03T05:50:57.303Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.284133561Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3272026-10-03T05:50:57.303Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.284250033Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3282026-10-03T05:50:57.303Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.284346738Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3292026-10-03T05:50:57.303Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.284474642Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3302026-10-03T05:50:57.335Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.325562126Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3312026-10-03T05:50:57.359Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.338834012Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":54}
3322026-10-03T05:50:57.359Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.338914185Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3332026-10-03T05:50:57.359Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.338986132Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"6f9338f2-5254-4232-ac41-c2c66df689c9","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3342026-10-03T05:50:57.359Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.339051577Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","vm":"migration_from_base_lifecycle_0","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3352026-10-03T05:50:57.359Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.339660548Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","vm":"migration_from_base_lifecycle_0","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3362026-10-03T05:50:58.008Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.998328753Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 0a7a8f19-e61a-4c55-a1c1-9758b600148f, name: \"phd-vm-0a7a8f19-e61a-4c55-a1c1-9758b600148f\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 48406fbc-45a9-4645-94d3-41b019078bc5, project_id: c2c4032e-763f-4ccc-b741-993b02fc7cdb, sled_id: e11e80c1-7649-459f-90c3-062e30826317, sled_serial: \"e11e80c1-7649-459f-90c3-062e30826317\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","vm":"migration_from_base_lifecycle_0","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3372026-10-03T05:50:58.008Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:50:57.998513175Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","migration_id":"6f9338f2-5254-4232-ac41-c2c66df689c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3382026-10-03T05:51:00.465Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:00.455328679Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
3392026-10-03T05:51:01.169Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:01.159334544Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3402026-10-03T05:51:01.169Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:01.159412593Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","migration_id":"6f9338f2-5254-4232-ac41-c2c66df689c9","elapsed_milliseconds":3160,"path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3412026-10-03T05:51:01.192Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:01.161978317Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3422026-10-03T05:51:01.192Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:01.162263Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3432026-10-03T05:51:01.192Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:01.162326722Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3442026-10-03T05:51:01.192Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:01.163317542Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3452026-10-03T05:51:01.254Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:01.244826337Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":82}
3462026-10-03T05:51:01.277Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:01.245002333Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":9601}
3472026-10-03T05:51:03.330Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.320579161Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":2158}
3482026-10-03T05:51:03.353Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.320956871Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3492026-10-03T05:51:03.353Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.321077151Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3502026-10-03T05:51:03.376Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.354193139Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":33}
3512026-10-03T05:51:03.376Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.354394172Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3522026-10-03T05:51:03.376Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.354710516Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3532026-10-03T05:51:03.376Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.354830825Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3542026-10-03T05:51:03.376Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.354930906Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3552026-10-03T05:51:03.377Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.354936968Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10931}
3562026-10-03T05:51:03.377Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.35665247Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3572026-10-03T05:51:03.926Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:03.916249752Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3582026-10-03T05:51:04.014Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.004867135Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3592026-10-03T05:51:04.014Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.004973377Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-03dd6d43-8273-4599-8570-a27dc2769969\"]","verb":"destroy","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3602026-10-03T05:51:04.041Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.031421166Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3612026-10-03T05:51:04.041Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.031515506Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-74355da4-0179-48e8-a622-24b3b35942ae\"]","verb":"destroy","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
3622026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.050674161Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":695}
3632026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.050822293Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","target":"migration_from_base_lifecycle_0","elapsed_milliseconds":6711,"vm":"migration_from_base_lifecycle_0","source":"migration_from_base"}
3642026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.05089397Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":695}
3652026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.050894481Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"b9a9cb14-a826-4c81-a906-93062c424b36","target_id":"0a7a8f19-e61a-4c55-a1c1-9758b600148f","elapsed_milliseconds":6711,"path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3662026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.050949315Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":12520}
3672026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.050971969Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3682026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.051023898Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3692026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.051066128Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3702026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.051236012Z","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"}
3712026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.051340902Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3722026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.051409573Z","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"}
3732026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.051477513Z","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"}
3742026-10-03T05:51:04.064Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.051547025Z","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"}
3752026-10-03T05:51:04.087Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.062929507Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-10-03T05:51:04.087Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.063123007Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-71d0da23-9127-43e4-87fd-7348593e8060\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-10-03T05:51:04.110Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.081677397Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-71d0da23-9127-43e4-87fd-7348593e8060\", \"phd-artifacts/phd-clone-d90cb244-6868-4ef3-97e6-f1b00375ed5d\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-10-03T05:51:04.110Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.100042658Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-d90cb244-6868-4ef3-97e6-f1b00375ed5d\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-10-03T05:51:04.133Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.111998434Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-d90cb244-6868-4ef3-97e6-f1b00375ed5d 0B 25.3T 1.30G /phd-artifacts/phd-clone-d90cb244-6868-4ef3-97e6-f1b00375ed5d\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-10-03T05:51:04.133Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.112742092Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3812026-10-03T05:51:04.133Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.112820813Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-10-03T05:51:04.133Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.112908991Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/307d7cf409a11795bd2f449aff90849e1cd9fd6e26ea2c6267e3110786362da9/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-10-03T05:51:04.133Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.112979535Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/307d7cf409a11795bd2f449aff90849e1cd9fd6e26ea2c6267e3110786362da9/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-10-03T05:51:04.133Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.113057925Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-10-03T05:51:04.168Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 937","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.15894399Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3862026-10-03T05:51:04.191Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.173320603Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":60}
3872026-10-03T05:51:04.191Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.173434992Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3882026-10-03T05:51:04.191Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.174150516Z","target":"phd_framework::test_vm","line":455,"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":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3892026-10-03T05:51:04.917Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.907945054Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3902026-10-03T05:51:04.961Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.909134252Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: ae72af00-9ae9-4133-8d29-67647c4e30e2, name: \"phd-vm-ae72af00-9ae9-4133-8d29-67647c4e30e2\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 84a8003e-7a05-4eee-a694-abccff82a247, project_id: c34a9713-ab12-40ce-acf8-c4f606a3889c, sled_id: fe5543d3-baaf-4536-9ca6-04fe4953de29, sled_serial: \"fe5543d3-baaf-4536-9ca6-04fe4953de29\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3912026-10-03T05:51:04.961Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.909297634Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3922026-10-03T05:51:04.961Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.909355043Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3932026-10-03T05:51:04.961Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.910348929Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
3942026-10-03T05:51:04.961Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.910434562Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3952026-10-03T05:51:04.961Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.910496641Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","timeout_duration":"300s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-10-03T05:51:04.961Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.91054895Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972026-10-03T05:51:04.961Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.910596571Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3982026-10-03T05:51:04.961Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:04.910648049Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3992026-10-03T05:51:10.007Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.565989906Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4655,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4002026-10-03T05:51:10.007Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.566083574Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012026-10-03T05:51:10.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.566281772Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4022026-10-03T05:51:10.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.566338641Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4032026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.566381833Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4042026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.58531202Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4052026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.585414917Z","target":"phd_framework::test_vm","line":847,"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"}
4062026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.585619898Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4072026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.585677698Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4082026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.585728174Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4092026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.619042079Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4102026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.6191838Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4112026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.619326611Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4708}
4122026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.619584483Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4132026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.619691577Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4142026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.629463597Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4152026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.629752107Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4162026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.629862468Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4172026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.663319515Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4182026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.663627011Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4192026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.663731591Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4202026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.674234395Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4212026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.674492527Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4222026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.67460422Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4232026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.707843282Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4242026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.708160086Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4252026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.708273903Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4262026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.718748152Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4272026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.718980085Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4282026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.719081288Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4292026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.752333093Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4302026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.752673453Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4312026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.752789554Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4322026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.763714552Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4332026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.76411723Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4342026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.764244362Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4352026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.797265067Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4362026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.797525113Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4372026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.797631686Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4382026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.808284196Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4392026-10-03T05:51:10.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.808529093Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4402026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.808634293Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4412026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.840675911Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4422026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.840926228Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4432026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.84104238Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4442026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.851629925Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4452026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.851867548Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4462026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.851978891Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4472026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.885077945Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4482026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.885273678Z","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"}
4492026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.885413525Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.885503847Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.885624608Z","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"}
4522026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.885722054Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.885851881Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.926042412Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4552026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.939707056Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":54}
4562026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.939810854Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626"}
4572026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.939893591Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d0a848a4-773c-4020-9ae2-07fe0b09b94c","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626"}
4582026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.939960008Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","vm":"migration_from_base_and_back_lifecycle_0"}
4592026-10-03T05:51:10.257Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:09.94058463Z","target":"phd_framework::test_vm","line":455,"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":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","vm":"migration_from_base_and_back_lifecycle_0"}
4602026-10-03T05:51:10.484Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:10.473814099Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 6e7455ec-0ac8-4901-939c-2b6a2a60d626, name: \"phd-vm-6e7455ec-0ac8-4901-939c-2b6a2a60d626\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 84a8003e-7a05-4eee-a694-abccff82a247, project_id: c34a9713-ab12-40ce-acf8-c4f606a3889c, sled_id: ec3c9a4e-032d-4a7b-9cc8-d7e8df44f833, sled_serial: \"ec3c9a4e-032d-4a7b-9cc8-d7e8df44f833\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","vm":"migration_from_base_and_back_lifecycle_0"}
4612026-10-03T05:51:10.484Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:10.473977631Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","migration_id":"d0a848a4-773c-4020-9ae2-07fe0b09b94c"}
4622026-10-03T05:51:13.039Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:13.028874035Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
4632026-10-03T05:51:14.222Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.211936147Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626"}
4642026-10-03T05:51:14.222Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.212015258Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3737,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","migration_id":"d0a848a4-773c-4020-9ae2-07fe0b09b94c"}
4652026-10-03T05:51:14.245Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.21427596Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4662026-10-03T05:51:14.245Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.21453256Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4672026-10-03T05:51:14.245Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.21459063Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4682026-10-03T05:51:14.245Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.216056346Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4692026-10-03T05:51:14.309Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.299037817Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":84,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4702026-10-03T05:51:14.332Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.29922289Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10125,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2"}
4712026-10-03T05:51:14.332Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.299452398Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":84,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626"}
4722026-10-03T05:51:14.332Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.299670604Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4732026-10-03T05:51:14.332Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.299742942Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4742026-10-03T05:51:14.375Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.326617374Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":26,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626"}
4752026-10-03T05:51:14.375Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.326760928Z","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"}
4762026-10-03T05:51:14.375Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.326889123Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772026-10-03T05:51:14.375Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.326979896Z","target":"phd_framework::test_vm","line":318,"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"}
4782026-10-03T05:51:14.375Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.327098592Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/307d7cf409a11795bd2f449aff90849e1cd9fd6e26ea2c6267e3110786362da9/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-10-03T05:51:14.375Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.327200917Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9004","server_path":"\"/phd-artifacts/307d7cf409a11795bd2f449aff90849e1cd9fd6e26ea2c6267e3110786362da9/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-10-03T05:51:14.375Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.327335995Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-10-03T05:51:14.419Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 940","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.371137773Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4822026-10-03T05:51:14.419Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.385259379Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":58}
4832026-10-03T05:51:14.419Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.385359801Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7"}
4842026-10-03T05:51:14.419Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.38543787Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"81558b90-de79-4635-bf47-bcda4201ddd5","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7"}
4852026-10-03T05:51:14.419Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.385517061Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","vm":"migration_from_base_and_back_lifecycle_1"}
4862026-10-03T05:51:14.419Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:14.386125542Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","vm":"migration_from_base_and_back_lifecycle_1"}
4872026-10-03T05:51:15.212Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:15.201653898Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: a3d43092-a581-4a39-95d8-ed717871ecf7, name: \"phd-vm-a3d43092-a581-4a39-95d8-ed717871ecf7\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 84a8003e-7a05-4eee-a694-abccff82a247, project_id: c34a9713-ab12-40ce-acf8-c4f606a3889c, sled_id: e1b776eb-0b48-43f8-925e-7cc3a77afeb2, sled_serial: \"e1b776eb-0b48-43f8-925e-7cc3a77afeb2\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","vm":"migration_from_base_and_back_lifecycle_1"}
4882026-10-03T05:51:15.212Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:15.201862967Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","migration_id":"81558b90-de79-4635-bf47-bcda4201ddd5"}
4892026-10-03T05:51:17.717Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:17.706259786Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7894}}"}
4902026-10-03T05:51:19.343Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.333316847Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7"}
4912026-10-03T05:51:19.344Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.333399565Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4131,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","migration_id":"81558b90-de79-4635-bf47-bcda4201ddd5"}
4922026-10-03T05:51:19.367Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.336325105Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4932026-10-03T05:51:19.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.336580873Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4942026-10-03T05:51:19.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.336648081Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4952026-10-03T05:51:19.367Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.338045727Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4962026-10-03T05:51:19.440Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.430653309Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":94,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626"}
4972026-10-03T05:51:19.464Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.430971667Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9490,"target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626"}
4982026-10-03T05:51:19.464Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.431108918Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ae72af00-9ae9-4133-8d29-67647c4e30e2","target_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","elapsed_milliseconds":9490}
4992026-10-03T05:51:19.464Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.431116433Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":94,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7"}
5002026-10-03T05:51:19.464Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.431353876Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5012026-10-03T05:51:19.464Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.431438708Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5022026-10-03T05:51:19.508Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.464956232Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7"}
5032026-10-03T05:51:19.508Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.465088465Z","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"}
5042026-10-03T05:51:19.508Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.465241054Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5052026-10-03T05:51:19.508Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.465330286Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_2","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"}
5062026-10-03T05:51:19.508Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.465427212Z","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"}
5072026-10-03T05:51:19.508Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.465479634Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9006","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-10-03T05:51:19.508Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.465617261Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-10-03T05:51:19.532Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 942","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.509395135Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5102026-10-03T05:51:19.555Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.52313845Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":57}
5112026-10-03T05:51:19.555Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.523247598Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547"}
5122026-10-03T05:51:19.555Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.523329033Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"ff47fe99-1c45-4284-ae2c-793516a1fd6b","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547"}
5132026-10-03T05:51:19.555Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.523402614Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","vm":"migration_from_base_and_back_lifecycle_2"}
5142026-10-03T05:51:19.555Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:19.524002167Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","vm":"migration_from_base_and_back_lifecycle_2"}
5152026-10-03T05:51:20.124Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:20.113178211Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 9f5b9355-9830-4dd4-9859-4cc5a8489547, name: \"phd-vm-9f5b9355-9830-4dd4-9859-4cc5a8489547\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 84a8003e-7a05-4eee-a694-abccff82a247, project_id: c34a9713-ab12-40ce-acf8-c4f606a3889c, sled_id: dc5b92b1-a0ef-48ec-9a77-60660724811e, sled_serial: \"dc5b92b1-a0ef-48ec-9a77-60660724811e\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","vm":"migration_from_base_and_back_lifecycle_2"}
5162026-10-03T05:51:20.124Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:20.113403952Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","migration_id":"ff47fe99-1c45-4284-ae2c-793516a1fd6b"}
5172026-10-03T05:51:22.602Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:22.592721324Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7941}}"}
5182026-10-03T05:51:23.986Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:23.975926745Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547"}
5192026-10-03T05:51:23.986Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:23.976009523Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3862,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","migration_id":"ff47fe99-1c45-4284-ae2c-793516a1fd6b"}
5202026-10-03T05:51:24.009Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:23.978526835Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5212026-10-03T05:51:24.009Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:23.978821797Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5222026-10-03T05:51:24.009Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:23.978904295Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5232026-10-03T05:51:24.009Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:23.9804957Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5242026-10-03T05:51:24.068Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.058300528Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":79,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7"}
5252026-10-03T05:51:24.091Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.058575422Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9672,"target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"a3d43092-a581-4a39-95d8-ed717871ecf7"}
5262026-10-03T05:51:24.091Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.058726891Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"6e7455ec-0ac8-4901-939c-2b6a2a60d626","target_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","elapsed_milliseconds":9673}
5272026-10-03T05:51:24.091Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.05881561Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":79,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547"}
5282026-10-03T05:51:24.091Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.059139308Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5292026-10-03T05:51:24.091Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.059238427Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5302026-10-03T05:51:24.114Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.091112635Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547"}
5312026-10-03T05:51:24.114Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.091300703Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5322026-10-03T05:51:24.114Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.091500514Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5332026-10-03T05:51:24.114Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.091606016Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":19183}
5342026-10-03T05:51:24.114Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.092021689Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5352026-10-03T05:51:24.114Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.092119485Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5362026-10-03T05:51:24.114Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.093090628Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5372026-10-03T05:51:24.828Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.817537421Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5382026-10-03T05:51:24.917Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.906994095Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5392026-10-03T05:51:24.917Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.907110347Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-d90cb244-6868-4ef3-97e6-f1b00375ed5d\"]","verb":"destroy","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5402026-10-03T05:51:24.943Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.933616174Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5412026-10-03T05:51:24.986Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.933680216Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-71d0da23-9127-43e4-87fd-7348593e8060\"]","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5422026-10-03T05:51:24.986Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.950487384Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":858,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547"}
5432026-10-03T05:51:24.987Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.950722282Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":5427,"target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547"}
5442026-10-03T05:51:24.987Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.950749574Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":858}
5452026-10-03T05:51:24.987Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.950844415Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"a3d43092-a581-4a39-95d8-ed717871ecf7","target_id":"9f5b9355-9830-4dd4-9859-4cc5a8489547","elapsed_milliseconds":5427}
5462026-10-03T05:51:24.987Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.950920821Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":20899}
5472026-10-03T05:51:24.987Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.950927964Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5482026-10-03T05:51:24.987Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.951013197Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5492026-10-03T05:51:24.987Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 90.99s
5502026-10-03T05:51:24.987Z
5512026-10-03T05:51:24.987Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-03T05:51:24.953527774Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5522026-10-03T05:51:25.086Z
5532026-10-03T05:51:25.087Zreal 1:34.201219399
5542026-10-03T05:51:25.110Zuser 50.757825056
5552026-10-03T05:51:25.110Zsys 21.751331365
5562026-10-03T05:51:25.110Ztrap 0.007738865
5572026-10-03T05:51:25.110Ztflt 0.004941195
5582026-10-03T05:51:25.110Zdflt 0.001551695
5592026-10-03T05:51:25.110Zkflt 0.000000000
5602026-10-03T05:51:25.110Zlock 3:39:44.962727699
5612026-10-03T05:51:25.110Zslp 4:23.954297936
5622026-10-03T05:51:25.110Zlat 2.134696968
5632026-10-03T05:51:25.110Zstop 44.299994737
5642026-10-03T05:51:25.110Z+ failcount=0
5652026-10-03T05:51:25.110Z+ set -e
5662026-10-03T05:51:25.110Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5672026-10-03T05:51:25.154ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5682026-10-03T05:51:25.154Za ./ 0K
5692026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::serial_history/ 0K
5702026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 157K
5712026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5722026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5732026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 164K
5742026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5752026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5762026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 157K
5772026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5782026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5792026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 164K
5802026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5812026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5822026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 158K
5832026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5842026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5852026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 268K
5862026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5872026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 268K
5882026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5892026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 164K
5902026-10-03T05:51:25.154Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5912026-10-03T05:51:25.154Z+ exitcode=0
5922026-10-03T05:51:25.155Z+ '[' 0 -eq 0 ']'
5932026-10-03T05:51:25.155Z+ echo
5942026-10-03T05:51:25.155Z+ echo 'ALL TESTS PASSED'
5952026-10-03T05:51:25.155Z+ echo
5962026-10-03T05:51:25.155Z
5972026-10-03T05:51:25.155ZALL TESTS PASSED
5982026-10-03T05:51:25.155Z
5992026-10-03T05:51:25.155Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6002026-10-03T05:51:25.155Z+ read
6012026-10-03T05:51:25.155Z+ exit 0
6022026-10-03T05:51:25.155Zprocess exited: duration 165287 ms, exit code 0
 
6032026-10-03T05:51:25.229Zfound 2 output files
6042026-10-03T05:51:25.229Zuploading: /tmp/phd-runner.log (184370 bytes)
6052026-10-03T05:51:26.434Zuploaded: /tmp/phd-runner.log
6062026-10-03T05:51:26.434Zuploading: /tmp/phd-tmp-files.tar.gz (133692 bytes)
6072026-10-03T05:51:27.615Zuploaded: /tmp/phd-tmp-files.tar.gz