01KPA92ERJNKE8J5X4GGDHQRZP: 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: 01KPA92R0EJ35143D190X4ER6S

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-04-16T04:42:30.839Zjob dependencies complete; ready to run (waiting for 8 m 22 s)
22026-04-16T04:45:53.395Zjob assigned to worker 01KPA9J32FHMKZX8PFANKCJK5Y [factory edgar, gimlet/BRM42220010/772] (queued for 3 m 22 s)
32026-04-16T04:45:54.326Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-04-16T04:45:54.350Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-04-16T04:45:54.350Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-04-16T04:45:54.377Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-04-16T04:45:54.401Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-04-16T04:46:00.356Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-04-16T04:46:00.356Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-04-16T04:46:00.403Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-04-16T04:46:00.403Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-04-16T04:46:09.664Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
132026-04-16T04:46:09.664Zstarting task 0: "setup"
142026-04-16T04:46:09.688Z++ uname -s
152026-04-16T04:46:09.688Z+ kern=SunOS
162026-04-16T04:46:09.688Z+ build_user=build
172026-04-16T04:46:09.688Z+ build_uid=12345
182026-04-16T04:46:09.688Z+ work_dir=/work
192026-04-16T04:46:09.688Z+ input_dir=/input
202026-04-16T04:46:09.688Z+ [[ 0 == 12345 ]]
212026-04-16T04:46:09.688Z+ case "$kern" in
222026-04-16T04:46:09.689Z+ groupadd -g 12345 build
232026-04-16T04:46:09.713Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
242026-04-16T04:46:11.700Z+ zfs create -o mountpoint=/work rpool/work
252026-04-16T04:46:11.888Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
262026-04-16T04:46:11.912Z+ home_fs=
272026-04-16T04:46:11.913Z+ [[ '' == autofs ]]
282026-04-16T04:46:11.913Z+ mkdir -p /home/build
292026-04-16T04:46:11.913Z+ chown build:build /home/build /work
302026-04-16T04:46:13.901Z+ chmod 0700 /home/build /work
312026-04-16T04:46:13.926Zprocess exited: duration 4243 ms, exit code 0
 
322026-04-16T04:46:13.974Zstarting task 1: "authentication"
332026-04-16T04:46:14.060Zprocess exited: duration 70 ms, exit code 0
 
342026-04-16T04:46:14.124Zstarting task 2: "build"
352026-04-16T04:46:14.156Z+ indir=/input
362026-04-16T04:46:14.157Z+ indir_suffix='phd-build/out/*.tar.gz'
372026-04-16T04:46:14.157Z+ phddir=/work/phd-test
382026-04-16T04:46:14.157Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
392026-04-16T04:46:14.181Z++ pilot local disk list -H -o type,disk
402026-04-16T04:46:14.182Z++ grep -v M.2
412026-04-16T04:46:14.182Z++ cut -f 2
422026-04-16T04:46:14.222Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
432026-04-16T04:46:14.506Z+ artifactdir=/phd-artifacts
442026-04-16T04:46:14.506Z+ banner Inputs
452026-04-16T04:46:14.531Z ###
462026-04-16T04:46:14.531Z # # # ##### # # ##### ####
472026-04-16T04:46:14.531Z # ## # # # # # # #
482026-04-16T04:46:14.531Z # # # # # # # # # ####
492026-04-16T04:46:14.531Z # # # # ##### # # # #
502026-04-16T04:46:14.531Z # # ## # # # # # #
512026-04-16T04:46:14.531Z ### # # # #### # ####
522026-04-16T04:46:14.531Z
532026-04-16T04:46:14.531Z+ find /input -ls
542026-04-16T04:46:14.531Z 34 1 drwxr-xr-x 3 root root 3 Apr 16 04:45 /input
552026-04-16T04:46:14.531Z 2 1 drwxr-xr-x 3 root root 3 Apr 16 04:45 /input/phd-build
562026-04-16T04:46:14.531Z 3 2 drwxr-xr-x 2 root root 7 Apr 16 04:46 /input/phd-build/out
572026-04-16T04:46:14.531Z 129 1 -rw-r--r-- 1 root root 65 Apr 16 04:45 /input/phd-build/out/phd-runner.sha256.txt
582026-04-16T04:46:14.531Z 128 2 -rw-r--r-- 1 root root 2573 Apr 16 04:45 /input/phd-build/out/phd-run-with-args.sh
592026-04-16T04:46:14.531Z 384 205132 -rw-r--r-- 1 root root 210095770 Apr 16 04:46 /input/phd-build/out/propolis-server-debug.tar.gz
602026-04-16T04:46:14.531Z 256 1 -rw-r--r-- 1 root root 65 Apr 16 04:46 /input/phd-build/out/propolis-server-debug.sha256.txt
612026-04-16T04:46:14.531Z 130 117558 -rw-r--r-- 1 root root 120317757 Apr 16 04:46 /input/phd-build/out/phd-runner.tar.gz
622026-04-16T04:46:14.531Z+ rm -rf /work/phd-test
632026-04-16T04:46:14.531Z+ mkdir /work/phd-test
642026-04-16T04:46:14.531Z+ for p in $indir/$indir_suffix
652026-04-16T04:46:14.531Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
662026-04-16T04:46:17.638ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
672026-04-16T04:46:17.638Zx phd-runner, 426501688 bytes, 833012 tape blocks
682026-04-16T04:46:17.638Zx artifacts.toml, 548 bytes, 2 tape blocks
692026-04-16T04:46:17.662Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
702026-04-16T04:46:20.804Z+ for f in $(tar tf "$p")
712026-04-16T04:46:20.804Z+ chmod +x /work/phd-test/phd-runner
722026-04-16T04:46:20.828Z+ for f in $(tar tf "$p")
732026-04-16T04:46:20.828Z+ chmod +x /work/phd-test/artifacts.toml
742026-04-16T04:46:20.828Z+ for p in $indir/$indir_suffix
752026-04-16T04:46:20.828Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
762026-04-16T04:46:31.478ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
772026-04-16T04:46:31.478Zx propolis-server, 799675408 bytes, 1561867 tape blocks
782026-04-16T04:46:31.502Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
792026-04-16T04:46:36.920Z+ for f in $(tar tf "$p")
802026-04-16T04:46:36.920Z+ chmod +x /work/phd-test/propolis-server
812026-04-16T04:46:36.944Z+ ls /work/phd-test
822026-04-16T04:46:36.944Zartifacts.toml
832026-04-16T04:46:36.944Zphd-runner
842026-04-16T04:46:36.944Zpropolis-server
852026-04-16T04:46:36.945Z+ banner Setup
862026-04-16T04:46:36.945Z #####
872026-04-16T04:46:36.945Z# # ###### ##### # # #####
882026-04-16T04:46:36.945Z# # # # # # #
892026-04-16T04:46:36.945Z ##### ##### # # # # #
902026-04-16T04:46:36.945Z # # # # # #####
912026-04-16T04:46:36.945Z# # # # # # #
922026-04-16T04:46:36.945Z ##### ###### # #### #
932026-04-16T04:46:36.945Z
942026-04-16T04:46:36.945Z+ tmpdir=/tmp/propolis-phd
952026-04-16T04:46:36.945Z+ '[' '!' -d /tmp/propolis-phd ']'
962026-04-16T04:46:36.945Z+ mkdir /tmp/propolis-phd
972026-04-16T04:46:36.945Z+ pfexec /usr/lib/rsrvrctl -s 4096
982026-04-16T04:46:37.432Z+ banner Tests
992026-04-16T04:46:37.456Z#######
1002026-04-16T04:46:37.456Z # ###### #### ##### ####
1012026-04-16T04:46:37.456Z # # # # #
1022026-04-16T04:46:37.456Z # ##### #### # ####
1032026-04-16T04:46:37.456Z # # # # #
1042026-04-16T04:46:37.456Z # # # # # # #
1052026-04-16T04:46:37.456Z # ###### #### # ####
1062026-04-16T04:46:37.457Z
1072026-04-16T04:46:37.457Z+ runner=/work/phd-test/phd-runner
1082026-04-16T04:46:37.457Z+ artifacts=/work/phd-test/artifacts.toml
1092026-04-16T04:46:37.457Z+ propolis=/work/phd-test/propolis-server
1102026-04-16T04:46:37.457Z+ ls /work/phd-test/phd-runner
1112026-04-16T04:46:37.457Z/work/phd-test/phd-runner
1122026-04-16T04:46:37.457Z+ ls /work/phd-test/artifacts.toml
1132026-04-16T04:46:37.457Z/work/phd-test/artifacts.toml
1142026-04-16T04:46:37.457Z+ ls /work/phd-test/propolis-server
1152026-04-16T04:46:37.457Z/work/phd-test/propolis-server
1162026-04-16T04:46:37.457Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1172026-04-16T04:46:37.457Z+ set +e
1182026-04-16T04:46:37.457Z+ RUST_BACKTRACE=1
1192026-04-16T04:46:37.457Z+ RUST_LOG=info,phd=debug
1202026-04-16T04:46:37.457Z+ 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
1212026-04-16T04:46:37.457Z+ tee /tmp/phd-runner.log
1222026-04-16T04:46:37.684Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:37.654791837Z","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 }"}
1232026-04-16T04:46:37.711Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:37.689871871Z","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: 192, tv_nsec: 486827091 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1242026-04-16T04:46:37.711Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:37.689995496Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1252026-04-16T04:46:37.734Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:37.693768734Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"ae1da83e66c648574827298f4bc444632bf4d047"}
1262026-04-16T04:46:37.735Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:37.696739683Z","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/ae1da83e66c648574827298f4bc444632bf4d047/crucible-nightly.sha256.txt","timeout":"600s"}
1272026-04-16T04:46:37.943Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:37.922345596Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1282026-04-16T04:46:38.459Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.438363817Z","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/bc489ddf0f38f75e0c194b86cf6f0de377f68845/propolis-server.sha256.txt"}
1292026-04-16T04:46:38.607Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.586391813Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1302026-04-16T04:46:38.631Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.586499408Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1312026-04-16T04:46:38.631Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.587584505Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1322026-04-16T04:46:38.631Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.587675708Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1332026-04-16T04:46:38.631Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.587721175Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1342026-04-16T04:46:38.631Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.587755049Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1352026-04-16T04:46:38.631Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.589698221Z","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"}
1362026-04-16T04:46:38.631Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.591044866Z","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::can_migrate_from_base"}
1372026-04-16T04:46:38.631Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:38.593339988Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1382026-04-16T04:46:39.267Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:39.245856194Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1392026-04-16T04:46:39.292Z{"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":827,"time":"2026-04-16T04:46:39.259570488Z","target":"phd_framework::artifacts::store","line":614,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1402026-04-16T04:46:46.179Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.157805096Z","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"}
1412026-04-16T04:46:46.180Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.157953899Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1422026-04-16T04:46:46.205Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.172289306Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2.09M 25.3T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1432026-04-16T04:46:46.205Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.172525236Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-0660db5a-c7c2-4bf3-9923-6c954e00979d\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1442026-04-16T04:46:46.230Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.198530733Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-0660db5a-c7c2-4bf3-9923-6c954e00979d\", \"phd-artifacts/phd-clone-2f4e2764-264d-4319-b99d-bfe8ffffe00f\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1452026-04-16T04:46:46.255Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.219820318Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-2f4e2764-264d-4319-b99d-bfe8ffffe00f\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1462026-04-16T04:46:46.255Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.230520761Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-2f4e2764-264d-4319-b99d-bfe8ffffe00f 0B 25.3T 48.9M /phd-artifacts/phd-clone-2f4e2764-264d-4319-b99d-bfe8ffffe00f\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1472026-04-16T04:46:46.280Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.234570776Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1482026-04-16T04:46:46.280Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.234657641Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1492026-04-16T04:46:46.280Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.234731291Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/6f8be65939adcee1790ec258829452e29e2dbac5c3dad2f42eacb3720d7f07fc/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1502026-04-16T04:46:46.280Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:46.23480915Z","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/bc489ddf0f38f75e0c194b86cf6f0de377f68845/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1512026-04-16T04:46:56.407Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:56.384948093Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/6f8be65939adcee1790ec258829452e29e2dbac5c3dad2f42eacb3720d7f07fc/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1522026-04-16T04:46:56.407Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:46:56.385050999Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1532026-04-16T04:47:15.520Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:15.498378626Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/6f8be65939adcee1790ec258829452e29e2dbac5c3dad2f42eacb3720d7f07fc/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1542026-04-16T04:47:15.520Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:15.498492232Z","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"}
1552026-04-16T04:47:15.697Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 832","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:15.675215577Z","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"}
1562026-04-16T04:47:15.721Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:15.688826392Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1572026-04-16T04:47:15.721Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:15.693427627Z","target":"phd_framework::test_vm","line":459,"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":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1582026-04-16T04:47:15.721Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:15.694136828Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":29459,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1592026-04-16T04:47:16.227Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.205161727Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1602026-04-16T04:47:16.273Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.208099669Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 8b89ad12-0313-490d-a22e-4acadad0bfef, name: \"phd-vm-8b89ad12-0313-490d-a22e-4acadad0bfef\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 7d77aa6e-6dd9-4d4f-b365-554b686f8c09, project_id: d14e9aaf-9146-4c28-b315-6abdc74cf33a, sled_id: 5f7f4efe-0220-4f1b-a205-7d5be8313f53, sled_serial: \"5f7f4efe-0220-4f1b-a205-7d5be8313f53\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1612026-04-16T04:47:16.273Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.208243763Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1622026-04-16T04:47:16.273Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.208300291Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1632026-04-16T04:47:16.273Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.209393323Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":1,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1642026-04-16T04:47:16.273Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.209478405Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1652026-04-16T04:47:16.273Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.209559129Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","timeout_duration":"300s","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1662026-04-16T04:47:16.273Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.209626948Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1672026-04-16T04:47:16.273Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.209674348Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1682026-04-16T04:47:16.273Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:16.209723031Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1692026-04-16T04:47:20.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.848642591Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4638,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1702026-04-16T04:47:20.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.848730618Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1712026-04-16T04:47:20.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.848991034Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1722026-04-16T04:47:20.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.849050538Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1732026-04-16T04:47:20.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.849090824Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1742026-04-16T04:47:20.896Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.867061627Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":17,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1752026-04-16T04:47:20.896Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.867171526Z","target":"phd_framework::test_vm","line":851,"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"}
1762026-04-16T04:47:20.896Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.867499691Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1772026-04-16T04:47:20.896Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.867595163Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1782026-04-16T04:47:20.896Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.867666409Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1792026-04-16T04:47:20.921Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.899389839Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1802026-04-16T04:47:20.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.899503565Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1812026-04-16T04:47:20.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.899574921Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4689,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
1822026-04-16T04:47:20.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.901556466Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1832026-04-16T04:47:20.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.902030929Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1842026-04-16T04:47:20.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.911159869Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1852026-04-16T04:47:20.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.91138094Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1862026-04-16T04:47:20.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.911474028Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1872026-04-16T04:47:20.970Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.944409504Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1882026-04-16T04:47:20.970Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.945293057Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1892026-04-16T04:47:20.970Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.945341329Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1902026-04-16T04:47:20.994Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.956132225Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1912026-04-16T04:47:20.994Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.956410685Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1922026-04-16T04:47:20.994Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.956503271Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1932026-04-16T04:47:21.019Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.989535785Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1942026-04-16T04:47:21.019Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.989772916Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1952026-04-16T04:47:21.019Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:20.989873077Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1962026-04-16T04:47:21.043Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.000420188Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1972026-04-16T04:47:21.043Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.000641019Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1982026-04-16T04:47:21.043Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.000733215Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
1992026-04-16T04:47:21.067Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.033750066Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2002026-04-16T04:47:21.068Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.03399351Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2012026-04-16T04:47:21.068Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.034092769Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2022026-04-16T04:47:21.068Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.044612708Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2032026-04-16T04:47:21.068Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.044849099Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2042026-04-16T04:47:21.068Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.044944641Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2052026-04-16T04:47:21.100Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.078079579Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2062026-04-16T04:47:21.124Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.078391784Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2072026-04-16T04:47:21.124Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.078468179Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2082026-04-16T04:47:21.124Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.088882798Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2092026-04-16T04:47:21.124Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.089007439Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2102026-04-16T04:47:21.124Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.089056525Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2112026-04-16T04:47:21.148Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.12217834Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2122026-04-16T04:47:21.149Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.122526243Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2132026-04-16T04:47:21.149Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.122581658Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2142026-04-16T04:47:21.173Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.132920583Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2152026-04-16T04:47:21.173Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.133150931Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2162026-04-16T04:47:21.173Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.133247415Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2172026-04-16T04:47:21.197Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.165966622Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2182026-04-16T04:47:21.197Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.166158147Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2192026-04-16T04:47:21.197Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.16628086Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2202026-04-16T04:47:21.197Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.166361604Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2212026-04-16T04:47:21.197Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.166912854Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","sha256":"None","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2222026-04-16T04:47:21.197Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.166971245Z","target":"phd_framework::artifacts::store","line":69,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2232026-04-16T04:47:21.197Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.167016562Z","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"}
2242026-04-16T04:47:21.197Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.167074753Z","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"}
2252026-04-16T04:47:21.232Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 833","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.210362449Z","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"}
2262026-04-16T04:47:21.257Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.225578594Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":59,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2272026-04-16T04:47:21.257Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.225674527Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
2282026-04-16T04:47:21.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":827,"time":"2026-04-16T04:47:21.225742456Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"7f4e76ee-c062-412a-9174-e43a2ed3c2a0","timeout_duration":"45s","source":"migration_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
2292026-04-16T04:47:21.257Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.225815706Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","vm":"migration_from_base_lifecycle_0","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
2302026-04-16T04:47:21.257Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.226414386Z","target":"phd_framework::test_vm","line":459,"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_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","vm":"migration_from_base_lifecycle_0","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
2312026-04-16T04:47:21.806Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.783626222Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 6af75c76-94b5-4006-bbd6-62e4f8f89690, name: \"phd-vm-6af75c76-94b5-4006-bbd6-62e4f8f89690\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 7d77aa6e-6dd9-4d4f-b365-554b686f8c09, project_id: d14e9aaf-9146-4c28-b315-6abdc74cf33a, sled_id: 3403e761-151c-45a2-883a-3fd0719b6f55, sled_serial: \"3403e761-151c-45a2-883a-3fd0719b6f55\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","vm":"migration_from_base_lifecycle_0","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
2322026-04-16T04:47:21.830Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:21.784382894Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","migration_id":"7f4e76ee-c062-412a-9174-e43a2ed3c2a0","target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
2332026-04-16T04:47:24.493Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:24.471385398Z","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}}"}
2342026-04-16T04:47:26.088Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.065553346Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
2352026-04-16T04:47:26.088Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.06564981Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","migration_id":"7f4e76ee-c062-412a-9174-e43a2ed3c2a0","elapsed_milliseconds":4281,"target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
2362026-04-16T04:47:26.112Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.068538082Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2372026-04-16T04:47:26.112Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.069290255Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2382026-04-16T04:47:26.112Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.069356521Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2392026-04-16T04:47:26.112Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.071388271Z","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":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2402026-04-16T04:47:26.186Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.163993973Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":94,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2412026-04-16T04:47:26.210Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.164193823Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10475,"vm_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
2422026-04-16T04:47:26.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.164316096Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":94,"vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2432026-04-16T04:47:26.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.164526507Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2442026-04-16T04:47:26.210Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.164590749Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2452026-04-16T04:47:26.234Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.197740396Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2462026-04-16T04:47:26.234Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.197939455Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2472026-04-16T04:47:26.234Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.198219308Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2482026-04-16T04:47:26.234Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.19838818Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9993}
2492026-04-16T04:47:26.234Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.198447513Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2502026-04-16T04:47:26.234Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.198592569Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2512026-04-16T04:47:26.234Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.199622581Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2522026-04-16T04:47:26.708Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.686120074Z","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":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2532026-04-16T04:47:26.788Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.76585068Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2542026-04-16T04:47:26.788Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.76595563Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-2f4e2764-264d-4319-b99d-bfe8ffffe00f\"]","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2552026-04-16T04:47:26.815Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.793179759Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2562026-04-16T04:47:26.815Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.793240475Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-0660db5a-c7c2-4bf3-9923-6c954e00979d\"]","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2572026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.811443359Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":613,"vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
2582026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.811985712Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","vm_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":5586,"target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","target":"migration_from_base_lifecycle_0"}
2592026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812049594Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","source_id":"8b89ad12-0313-490d-a22e-4acadad0bfef","elapsed_milliseconds":5586,"target_id":"6af75c76-94b5-4006-bbd6-62e4f8f89690","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0"}
2602026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812096483Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":48221,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2612026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812113997Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":613}
2622026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812242061Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2632026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812293048Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2642026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812342081Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2652026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812483961Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2662026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.81257244Z","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::serial_history"}
2672026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812630581Z","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"}
2682026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812686968Z","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"}
2692026-04-16T04:47:26.840Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.812748986Z","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"}
2702026-04-16T04:47:26.865Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.824081704Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1014M 25.3T 1013M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2712026-04-16T04:47:26.865Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.82419507Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-5c255afa-accb-4eff-bc3e-766f57344e5f\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::serial_history"}
2722026-04-16T04:47:26.889Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.844795592Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-5c255afa-accb-4eff-bc3e-766f57344e5f\", \"phd-artifacts/phd-clone-1b8f792f-5972-44d6-9e2c-53c655b00e63\"]","path":"phd_tests::migrate::from_base::serial_history"}
2732026-04-16T04:47:26.889Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.86519065Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-1b8f792f-5972-44d6-9e2c-53c655b00e63\"]","path":"phd_tests::migrate::from_base::serial_history"}
2742026-04-16T04:47:26.914Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.876988203Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-1b8f792f-5972-44d6-9e2c-53c655b00e63 0B 25.3T 1013M /phd-artifacts/phd-clone-1b8f792f-5972-44d6-9e2c-53c655b00e63\n","path":"phd_tests::migrate::from_base::serial_history"}
2752026-04-16T04:47:26.914Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.877646627Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2762026-04-16T04:47:26.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.877712302Z","target":"phd_framework::test_vm","line":322,"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"}
2772026-04-16T04:47:26.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.877790441Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/6f8be65939adcee1790ec258829452e29e2dbac5c3dad2f42eacb3720d7f07fc/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2782026-04-16T04:47:26.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.877851848Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/6f8be65939adcee1790ec258829452e29e2dbac5c3dad2f42eacb3720d7f07fc/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"}
2792026-04-16T04:47:26.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.877923845Z","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::serial_history/migration_serial_history_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2802026-04-16T04:47:26.945Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 842","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.923162791Z","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"}
2812026-04-16T04:47:26.969Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.93754242Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":59,"path":"phd_tests::migrate::from_base::serial_history"}
2822026-04-16T04:47:26.969Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.937648031Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2832026-04-16T04:47:26.969Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:26.938315914Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2842026-04-16T04:47:27.461Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.439065807Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2852026-04-16T04:47:27.507Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.439814263Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 19b0e1fd-1bb6-466b-a944-ac67bda23f36, name: \"phd-vm-19b0e1fd-1bb6-466b-a944-ac67bda23f36\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: e07cc437-7cdb-42dd-bfea-2e205aa2ee13, project_id: 8f308ac3-3c6e-4d53-8dd0-076df406c5f4, sled_id: b14d7ed4-58e6-4437-a0a2-3c094402e228, sled_serial: \"b14d7ed4-58e6-4437-a0a2-3c094402e228\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2862026-04-16T04:47:27.507Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.439960351Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2872026-04-16T04:47:27.507Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.440015426Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2882026-04-16T04:47:27.507Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.440955687Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2892026-04-16T04:47:27.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.441029898Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2902026-04-16T04:47:27.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.441084332Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","timeout_duration":"300s","path":"phd_tests::migrate::from_base::serial_history"}
2912026-04-16T04:47:27.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.441127615Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
2922026-04-16T04:47:27.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.44116736Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2932026-04-16T04:47:27.507Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:27.441211214Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2942026-04-16T04:47:32.047Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.024801808Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4583,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2952026-04-16T04:47:32.047Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.024890377Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
2962026-04-16T04:47:32.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.025069698Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
2972026-04-16T04:47:32.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.025122058Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2982026-04-16T04:47:32.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.025161613Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
2992026-04-16T04:47:32.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.043038687Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":17,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3002026-04-16T04:47:32.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.043145631Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3012026-04-16T04:47:32.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.043451283Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3022026-04-16T04:47:32.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.043550272Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3032026-04-16T04:47:32.072Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.043588966Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3042026-04-16T04:47:32.098Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.076321147Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3052026-04-16T04:47:32.098Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.076425355Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3062026-04-16T04:47:32.122Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.076493315Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4635,"path":"phd_tests::migrate::from_base::serial_history"}
3072026-04-16T04:47:32.122Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.076675842Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3082026-04-16T04:47:32.123Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.076723864Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3092026-04-16T04:47:32.123Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.087220146Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3102026-04-16T04:47:32.123Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.087527802Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3112026-04-16T04:47:32.123Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.087632151Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3122026-04-16T04:47:32.147Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.12026871Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3132026-04-16T04:47:32.147Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.120580414Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3142026-04-16T04:47:32.147Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.120686556Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3152026-04-16T04:47:32.171Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.131165377Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3162026-04-16T04:47:32.171Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.131397689Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3172026-04-16T04:47:32.171Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.13149274Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3182026-04-16T04:47:32.195Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.163612986Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3192026-04-16T04:47:32.195Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.168924081Z","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"}
3202026-04-16T04:47:32.195Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.169062585Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3212026-04-16T04:47:32.195Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.16912311Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3222026-04-16T04:47:32.195Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.169198183Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
3232026-04-16T04:47:32.195Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.16925441Z","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::serial_history"}
3242026-04-16T04:47:32.195Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.169325426Z","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"}
3252026-04-16T04:47:32.235Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 843","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.212672577Z","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"}
3262026-04-16T04:47:32.259Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.224523752Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":55,"path":"phd_tests::migrate::from_base::serial_history"}
3272026-04-16T04:47:32.259Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.224610678Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","target":"migration_serial_history_base_lifecycle_0"}
3282026-04-16T04:47:32.259Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.224675722Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"c7641be2-de3b-48d1-96e0-782beec7bcf1","path":"phd_tests::migrate::from_base::serial_history","source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","target":"migration_serial_history_base_lifecycle_0"}
3292026-04-16T04:47:32.259Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.224742319Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5","path":"phd_tests::migrate::from_base::serial_history","source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0"}
3302026-04-16T04:47:32.259Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:32.225364083Z","target":"phd_framework::test_vm","line":459,"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":"c45e505f-696d-4cbb-b941-344acb959be5","path":"phd_tests::migrate::from_base::serial_history","source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0"}
3312026-04-16T04:47:33.115Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:33.092817127Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c45e505f-696d-4cbb-b941-344acb959be5, name: \"phd-vm-c45e505f-696d-4cbb-b941-344acb959be5\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: e07cc437-7cdb-42dd-bfea-2e205aa2ee13, project_id: 8f308ac3-3c6e-4d53-8dd0-076df406c5f4, sled_id: 4ca26fb9-74c1-4f8d-85f3-fd886e24d554, sled_serial: \"4ca26fb9-74c1-4f8d-85f3-fd886e24d554\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5","path":"phd_tests::migrate::from_base::serial_history","source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0"}
3322026-04-16T04:47:33.116Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:33.093015214Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"c7641be2-de3b-48d1-96e0-782beec7bcf1","path":"phd_tests::migrate::from_base::serial_history","source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","target":"migration_serial_history_base_lifecycle_0"}
3332026-04-16T04:47:35.793Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:35.771273191Z","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}}"}
3342026-04-16T04:47:36.810Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.787925431Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","target":"migration_serial_history_base_lifecycle_0"}
3352026-04-16T04:47:36.811Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.787981819Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"c7641be2-de3b-48d1-96e0-782beec7bcf1","path":"phd_tests::migrate::from_base::serial_history","source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","elapsed_milliseconds":3694,"target":"migration_serial_history_base_lifecycle_0"}
3362026-04-16T04:47:36.835Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.790867744Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3372026-04-16T04:47:36.835Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.7923459Z","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":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3382026-04-16T04:47:36.899Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.876784053Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":85,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3392026-04-16T04:47:36.923Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.877068165Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9939,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36"}
3402026-04-16T04:47:36.923Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.879765763Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5"}
3412026-04-16T04:47:36.923Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.879988998Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3422026-04-16T04:47:36.923Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.880132612Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9440}
3432026-04-16T04:47:36.923Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.880117764Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3442026-04-16T04:47:36.923Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.880211482Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3452026-04-16T04:47:36.923Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:36.88133394Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5"}
3462026-04-16T04:47:37.443Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.419677224Z","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":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5"}
3472026-04-16T04:47:37.521Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.499045299Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5"}
3482026-04-16T04:47:37.521Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.499177641Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-1b8f792f-5972-44d6-9e2c-53c655b00e63\"]","verb":"destroy","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5"}
3492026-04-16T04:47:37.546Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.523751211Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5"}
3502026-04-16T04:47:37.546Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.523810614Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-5c255afa-accb-4eff-bc3e-766f57344e5f\"]","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5"}
3512026-04-16T04:47:37.570Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.541291333Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":661,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5"}
3522026-04-16T04:47:37.570Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.541528916Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","vm_id":"c45e505f-696d-4cbb-b941-344acb959be5","elapsed_milliseconds":5316,"source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0"}
3532026-04-16T04:47:37.570Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.541577478Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":661}
3542026-04-16T04:47:37.570Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.541641921Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":5316,"path":"phd_tests::migrate::from_base::serial_history","source_id":"19b0e1fd-1bb6-466b-a944-ac67bda23f36","source":"migration_serial_history_base","target_id":"c45e505f-696d-4cbb-b941-344acb959be5","target":"migration_serial_history_base_lifecycle_0"}
3552026-04-16T04:47:37.570Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.541701715Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":10729,"path":"phd_tests::migrate::from_base::serial_history"}
3562026-04-16T04:47:37.570Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.541707286Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3572026-04-16T04:47:37.570Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.541758533Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3582026-04-16T04:47:37.571Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.541807366Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3592026-04-16T04:47:37.571Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.542008419Z","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"}
3602026-04-16T04:47:37.571Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.542137806Z","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"}
3612026-04-16T04:47:37.571Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.542202248Z","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"}
3622026-04-16T04:47:37.571Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.542264928Z","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"}
3632026-04-16T04:47:37.571Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.542333679Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3642026-04-16T04:47:37.595Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.552994366Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1014M 25.3T 1013M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3652026-04-16T04:47:37.595Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.55309589Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-8aaf4ba4-78a6-49d2-bcaf-32ed77f8b3a7\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3662026-04-16T04:47:37.619Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.574340336Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-8aaf4ba4-78a6-49d2-bcaf-32ed77f8b3a7\", \"phd-artifacts/phd-clone-ccdb3c76-ba5a-415c-8b46-c69c2ae9fea4\"]","verb":"clone","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3672026-04-16T04:47:37.619Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.59188132Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-ccdb3c76-ba5a-415c-8b46-c69c2ae9fea4\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3682026-04-16T04:47:37.643Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.602225053Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-ccdb3c76-ba5a-415c-8b46-c69c2ae9fea4 0B 25.3T 1013M /phd-artifacts/phd-clone-ccdb3c76-ba5a-415c-8b46-c69c2ae9fea4\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3692026-04-16T04:47:37.643Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.602907704Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3702026-04-16T04:47:37.643Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.602972447Z","target":"phd_framework::test_vm","line":322,"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"}
3712026-04-16T04:47:37.643Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.603054083Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/6f8be65939adcee1790ec258829452e29e2dbac5c3dad2f42eacb3720d7f07fc/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3722026-04-16T04:47:37.643Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.603121812Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/6f8be65939adcee1790ec258829452e29e2dbac5c3dad2f42eacb3720d7f07fc/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3732026-04-16T04:47:37.643Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.603199309Z","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"}
3742026-04-16T04:47:37.670Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 852","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.647988808Z","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"}
3752026-04-16T04:47:37.694Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.662475552Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":59,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-04-16T04:47:37.694Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.662574541Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-04-16T04:47:37.694Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:37.663249577Z","target":"phd_framework::test_vm","line":459,"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":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-04-16T04:47:38.162Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.140077932Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3792026-04-16T04:47:38.208Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.141089248Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: e198b362-39dc-40d4-ad8c-8f15fa88fdce, name: \"phd-vm-e198b362-39dc-40d4-ad8c-8f15fa88fdce\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: b4e49b28-1d4c-47a0-88f6-79424a6ccbe0, project_id: faa7d763-4f7c-4338-9b59-de5f51278dcb, sled_id: f59bc5f1-bd9a-4abf-8817-d86e5527e995, sled_serial: \"f59bc5f1-bd9a-4abf-8817-d86e5527e995\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-04-16T04:47:38.208Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.141240146Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3812026-04-16T04:47:38.208Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.141291834Z","target":"phd_framework::test_vm","line":584,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-04-16T04:47:38.208Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.142424893Z","target":"phd_framework::test_vm","line":579,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":1,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-04-16T04:47:38.208Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.142535994Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-04-16T04:47:38.208Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.1426073Z","target":"phd_framework::test_vm","line":843,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","timeout_duration":"300s","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-04-16T04:47:38.208Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.142654981Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3862026-04-16T04:47:38.208Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.14270184Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3872026-04-16T04:47:38.208Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:38.142750653Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3882026-04-16T04:47:42.703Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.6801188Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":4537,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3892026-04-16T04:47:42.703Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.680207158Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3902026-04-16T04:47:42.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.680393012Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3912026-04-16T04:47:42.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.680446184Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3922026-04-16T04:47:42.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.680487553Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3932026-04-16T04:47:42.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.698682001Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3942026-04-16T04:47:42.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.698832738Z","target":"phd_framework::test_vm","line":851,"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"}
3952026-04-16T04:47:42.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.699179408Z","target":"phd_framework::test_vm","line":851,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-04-16T04:47:42.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.69928542Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972026-04-16T04:47:42.727Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.699366505Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3982026-04-16T04:47:42.754Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.731296727Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":31,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3992026-04-16T04:47:42.754Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.73141424Z","target":"phd_framework::test_vm","line":891,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4002026-04-16T04:47:42.754Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.731485226Z","target":"phd_framework::test_vm","line":894,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4588,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012026-04-16T04:47:42.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.731714573Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4022026-04-16T04:47:42.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.731829231Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4032026-04-16T04:47:42.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.742393405Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4042026-04-16T04:47:42.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.742630977Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4052026-04-16T04:47:42.779Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.742735085Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4062026-04-16T04:47:42.802Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.774932758Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4072026-04-16T04:47:42.803Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.775176974Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4082026-04-16T04:47:42.803Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.775273838Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4092026-04-16T04:47:42.827Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.786838878Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4102026-04-16T04:47:42.827Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.787077092Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4112026-04-16T04:47:42.827Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.787173436Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4122026-04-16T04:47:42.852Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.809715464Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4132026-04-16T04:47:42.852Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.809953848Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4142026-04-16T04:47:42.852Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.81004946Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4152026-04-16T04:47:42.852Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.820330985Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4162026-04-16T04:47:42.852Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.820621418Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4172026-04-16T04:47:42.852Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.820725266Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-04-16T04:47:42.876Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.853313754Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4192026-04-16T04:47:42.876Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.85353212Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4202026-04-16T04:47:42.876Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.853638773Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4212026-04-16T04:47:42.901Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.864219187Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4222026-04-16T04:47:42.901Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.8645198Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4232026-04-16T04:47:42.901Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.864599402Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4242026-04-16T04:47:42.925Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.886374841Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":21,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4252026-04-16T04:47:42.925Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.886663371Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4262026-04-16T04:47:42.925Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.886764574Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4272026-04-16T04:47:42.925Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.897375975Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4282026-04-16T04:47:42.925Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.897638105Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4292026-04-16T04:47:42.925Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.89769342Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4302026-04-16T04:47:42.953Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.930768925Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4312026-04-16T04:47:42.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.930967464Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4322026-04-16T04:47:42.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.931023661Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4332026-04-16T04:47:42.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.942801887Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4342026-04-16T04:47:42.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.943032506Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4352026-04-16T04:47:42.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.943129391Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4362026-04-16T04:47:43.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.965793604Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4372026-04-16T04:47:43.002Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.96591784Z","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"}
4382026-04-16T04:47:43.002Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.966037047Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4392026-04-16T04:47:43.002Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.966115857Z","target":"phd_framework::test_vm","line":322,"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"}
4402026-04-16T04:47:43.002Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.966224023Z","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"}
4412026-04-16T04:47:43.002Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.966309697Z","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"}
4422026-04-16T04:47:43.002Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:42.96642699Z","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_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4432026-04-16T04:47:43.030Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 853","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:43.007634494Z","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"}
4442026-04-16T04:47:43.054Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:43.020355055Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":54,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4452026-04-16T04:47:43.054Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:43.020433374Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4462026-04-16T04:47:43.054Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:43.020492687Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"c486c700-e2c4-404f-afa2-43e9f55e6945","source_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4472026-04-16T04:47:43.054Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:43.02055156Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4482026-04-16T04:47:43.054Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:43.021158856Z","target":"phd_framework::test_vm","line":459,"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":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4492026-04-16T04:47:43.698Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:43.675470705Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 96e5538e-2a13-4cad-ad27-b59671a704b7, name: \"phd-vm-96e5538e-2a13-4cad-ad27-b59671a704b7\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: b4e49b28-1d4c-47a0-88f6-79424a6ccbe0, project_id: faa7d763-4f7c-4338-9b59-de5f51278dcb, sled_id: 3a45b393-8e50-4026-9268-b1b2ed2436fb, sled_serial: \"3a45b393-8e50-4026-9268-b1b2ed2436fb\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-04-16T04:47:43.698Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:43.675644807Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","migration_id":"c486c700-e2c4-404f-afa2-43e9f55e6945","target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-04-16T04:47:46.378Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.355390327Z","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}}"}
4522026-04-16T04:47:46.642Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.618922762Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-04-16T04:47:46.642Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.61898999Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","migration_id":"c486c700-e2c4-404f-afa2-43e9f55e6945","elapsed_milliseconds":2943,"target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-04-16T04:47:46.666Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.621020337Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4552026-04-16T04:47:46.666Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.62120029Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4562026-04-16T04:47:46.666Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.621269412Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4572026-04-16T04:47:46.666Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.622791371Z","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":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4582026-04-16T04:47:46.734Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.711967179Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":90,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4592026-04-16T04:47:46.759Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.712187659Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm":"migration_from_base_and_back","elapsed_milliseconds":9049,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4602026-04-16T04:47:46.759Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.712460048Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":91,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4612026-04-16T04:47:46.759Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.712812018Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4622026-04-16T04:47:46.759Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.712879317Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4632026-04-16T04:47:46.783Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.746906954Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":34,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4642026-04-16T04:47:46.783Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.747036811Z","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"}
4652026-04-16T04:47:46.783Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.747156068Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4662026-04-16T04:47:46.783Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.747243314Z","target":"phd_framework::test_vm","line":322,"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"}
4672026-04-16T04:47:46.784Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.747374174Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/6f8be65939adcee1790ec258829452e29e2dbac5c3dad2f42eacb3720d7f07fc/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4682026-04-16T04:47:46.784Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.747470277Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/6f8be65939adcee1790ec258829452e29e2dbac5c3dad2f42eacb3720d7f07fc/propolis-server\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4692026-04-16T04:47:46.784Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.747592189Z","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_1.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4702026-04-16T04:47:46.815Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 855","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.792653736Z","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"}
4712026-04-16T04:47:46.840Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.806925552Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":59,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4722026-04-16T04:47:46.840Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.807025012Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4732026-04-16T04:47:46.840Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.807103091Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d24fb2be-84ad-42f5-ba56-521bbc0f4a62","timeout_duration":"45s","source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4742026-04-16T04:47:46.840Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.807178134Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4752026-04-16T04:47:46.840Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:46.807738571Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762026-04-16T04:47:47.351Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:47.327833503Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 28348a32-dd41-4521-91cf-8f57db64f7fb, name: \"phd-vm-28348a32-dd41-4521-91cf-8f57db64f7fb\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: b4e49b28-1d4c-47a0-88f6-79424a6ccbe0, project_id: faa7d763-4f7c-4338-9b59-de5f51278dcb, sled_id: 90b88dd7-81a7-45cb-90cf-39f6c8ed9569, sled_serial: \"90b88dd7-81a7-45cb-90cf-39f6c8ed9569\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772026-04-16T04:47:47.351Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:47.328004088Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","migration_id":"d24fb2be-84ad-42f5-ba56-521bbc0f4a62","target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-04-16T04:47:50.049Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:50.026614314Z","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}}"}
4792026-04-16T04:47:51.189Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.16655987Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-04-16T04:47:51.190Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.166637317Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","migration_id":"d24fb2be-84ad-42f5-ba56-521bbc0f4a62","elapsed_milliseconds":3838,"target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-04-16T04:47:51.214Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.168943931Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4822026-04-16T04:47:51.214Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.169163209Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4832026-04-16T04:47:51.214Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.169216611Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4842026-04-16T04:47:51.214Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.171617203Z","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":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4852026-04-16T04:47:51.275Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.252712199Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":83,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4862026-04-16T04:47:51.300Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.253025004Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":83,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4872026-04-16T04:47:51.300Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.252994156Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","elapsed_milliseconds":8232,"source_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","vm_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm":"migration_from_base_and_back_lifecycle_0","target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4882026-04-16T04:47:51.300Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.253118603Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e198b362-39dc-40d4-ad8c-8f15fa88fdce","elapsed_milliseconds":8232,"target_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4892026-04-16T04:47:51.300Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.253257477Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4902026-04-16T04:47:51.300Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.253354171Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4912026-04-16T04:47:51.324Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.279163243Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":25,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4922026-04-16T04:47:51.324Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.279257943Z","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"}
4932026-04-16T04:47:51.324Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.27935045Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4942026-04-16T04:47:51.324Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.279403821Z","target":"phd_framework::test_vm","line":322,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4952026-04-16T04:47:51.324Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.279476199Z","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"}
4962026-04-16T04:47:51.324Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.279533318Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4972026-04-16T04:47:51.324Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.279605485Z","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"}
4982026-04-16T04:47:51.348Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 857","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.322853578Z","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"}
4992026-04-16T04:47:51.372Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.33677636Z","target":"phd_framework::test_vm","line":304,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":57,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5002026-04-16T04:47:51.372Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.336879446Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5012026-04-16T04:47:51.372Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.336959839Z","target":"phd_framework::test_vm","line":646,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d8c0dfcd-2f6e-46b1-9fd7-b6ea05e6cdd7","timeout_duration":"45s","source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5022026-04-16T04:47:51.372Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.337038429Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5032026-04-16T04:47:51.372Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.33761656Z","target":"phd_framework::test_vm","line":459,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5042026-04-16T04:47:51.921Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.897835653Z","target":"phd_framework::test_vm","line":518,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: f594a51e-0eb7-45cf-b494-4ea97f911a50, name: \"phd-vm-f594a51e-0eb7-45cf-b494-4ea97f911a50\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: b4e49b28-1d4c-47a0-88f6-79424a6ccbe0, project_id: faa7d763-4f7c-4338-9b59-de5f51278dcb, sled_id: 391faefe-1fea-487e-8e72-b919ac5ea4d4, sled_serial: \"391faefe-1fea-487e-8e72-b919ac5ea4d4\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5052026-04-16T04:47:51.921Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:51.898021106Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","migration_id":"d8c0dfcd-2f6e-46b1-9fd7-b6ea05e6cdd7","target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-04-16T04:47:54.609Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:54.586361509Z","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}}"}
5072026-04-16T04:47:56.015Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:55.992364018Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-04-16T04:47:56.015Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:55.992441195Z","target":"phd_framework::test_vm","line":667,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","migration_id":"d8c0dfcd-2f6e-46b1-9fd7-b6ea05e6cdd7","elapsed_milliseconds":4094,"target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-04-16T04:47:56.039Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:55.995024015Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5102026-04-16T04:47:56.039Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:55.99537274Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5112026-04-16T04:47:56.039Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:55.995474574Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5122026-04-16T04:47:56.039Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:55.996930176Z","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":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5132026-04-16T04:47:56.108Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.086330023Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":89,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5142026-04-16T04:47:56.132Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.08657514Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":9278,"source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","vm_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm":"migration_from_base_and_back_lifecycle_1","target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5152026-04-16T04:47:56.132Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.086632192Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":90,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5162026-04-16T04:47:56.132Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.086703663Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"96e5538e-2a13-4cad-ad27-b59671a704b7","elapsed_milliseconds":9278,"target_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5172026-04-16T04:47:56.132Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.086835407Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5182026-04-16T04:47:56.132Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.086901478Z","target":"phd_framework::test_vm","line":924,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5192026-04-16T04:47:56.156Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.120533121Z","target":"phd_framework::test_vm","line":917,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5202026-04-16T04:47:56.156Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.120619536Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5212026-04-16T04:47:56.156Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.120864239Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5222026-04-16T04:47:56.156Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.121013801Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":17979}
5232026-04-16T04:47:56.156Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.121083253Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5242026-04-16T04:47:56.156Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.121190388Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5252026-04-16T04:47:56.156Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.122522522Z","target":"phd_framework::test_vm","line":1199,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5262026-04-16T04:47:56.582Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.565771659Z","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":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5272026-04-16T04:47:56.657Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.641977335Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5282026-04-16T04:47:56.657Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.642032311Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-ccdb3c76-ba5a-415c-8b46-c69c2ae9fea4\"]","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5292026-04-16T04:47:56.684Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.669369267Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5302026-04-16T04:47:56.684Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.669451041Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-8aaf4ba4-78a6-49d2-bcaf-32ed77f8b3a7\"]","verb":"destroy","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5312026-04-16T04:47:56.708Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.687052627Z","target":"phd_framework::test_vm","line":1176,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":559,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5322026-04-16T04:47:56.708Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.687260398Z","target":"phd_framework::test_vm","line":416,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":5341,"source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","vm_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","vm":"migration_from_base_and_back_lifecycle_2","target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5332026-04-16T04:47:56.708Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.687296504Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":559}
5342026-04-16T04:47:56.708Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.687341083Z","target":"phd_framework::test_vm","line":613,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"28348a32-dd41-4521-91cf-8f57db64f7fb","elapsed_milliseconds":5342,"target_id":"f594a51e-0eb7-45cf-b494-4ea97f911a50","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5352026-04-16T04:47:56.708Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.687389259Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":19137,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5362026-04-16T04:47:56.708Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.687397956Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5372026-04-16T04:47:56.708Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.68751059Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5382026-04-16T04:47:56.708Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 78.09s
5392026-04-16T04:47:56.708Z
5402026-04-16T04:47:56.708Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":827,"time":"2026-04-16T04:47:56.688096885Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5412026-04-16T04:47:56.834Z
5422026-04-16T04:47:56.834Zreal 1:19.249386847
5432026-04-16T04:47:56.834Zuser 44.051873066
5442026-04-16T04:47:56.834Zsys 20.485425361
5452026-04-16T04:47:56.834Ztrap 0.007119632
5462026-04-16T04:47:56.834Ztflt 0.003858658
5472026-04-16T04:47:56.859Zdflt 0.003178031
5482026-04-16T04:47:56.859Zkflt 0.000000000
5492026-04-16T04:47:56.859Zlock 3:07:21.483144706
5502026-04-16T04:47:56.859Zslp 4:03.579668917
5512026-04-16T04:47:56.859Zlat 1.849087350
5522026-04-16T04:47:56.859Zstop 53.330928109
5532026-04-16T04:47:56.859Z+ failcount=0
5542026-04-16T04:47:56.859Z+ set -e
5552026-04-16T04:47:56.859Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5562026-04-16T04:47:56.859ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5572026-04-16T04:47:56.859Za ./ 0K
5582026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5592026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 141K
5602026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5612026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5622026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 147K
5632026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5642026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::serial_history/ 0K
5652026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 141K
5662026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5672026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5682026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 148K
5692026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5702026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5712026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 141K
5722026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5732026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5742026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 235K
5752026-04-16T04:47:56.859Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5762026-04-16T04:47:56.860Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 235K
5772026-04-16T04:47:56.860Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5782026-04-16T04:47:56.860Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 147K
5792026-04-16T04:47:56.860Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5802026-04-16T04:47:56.860Z+ exitcode=0
5812026-04-16T04:47:56.860Z+ '[' 0 -eq 0 ']'
5822026-04-16T04:47:56.860Z+ echo
5832026-04-16T04:47:56.884Z
5842026-04-16T04:47:56.884Z+ echo 'ALL TESTS PASSED'
5852026-04-16T04:47:56.884Z+ echo
5862026-04-16T04:47:56.884ZALL TESTS PASSED
5872026-04-16T04:47:56.884Z
5882026-04-16T04:47:56.884Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5892026-04-16T04:47:56.884Z+ read
5902026-04-16T04:47:56.884Z+ exit 0
5912026-04-16T04:47:56.884Zprocess exited: duration 102744 ms, exit code 0
 
5922026-04-16T04:47:56.936Zfound 2 output files
5932026-04-16T04:47:56.936Zuploading: /tmp/phd-runner.log (184406 bytes)
5942026-04-16T04:47:58.081Zuploaded: /tmp/phd-runner.log
5952026-04-16T04:47:58.106Zuploading: /tmp/phd-tmp-files.tar.gz (106572 bytes)
5962026-04-16T04:47:59.263Zuploaded: /tmp/phd-tmp-files.tar.gz