01M4RXEGWWJDBZKFGCMCGNSVEE: 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: 01M4RXF6QEM2V9FK7HZB17BHJA

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-10-12T20:51:26.392Zjob dependencies complete; ready to run (waiting for 11 m 50 s)
22026-10-12T21:18:17.638Zjob assigned to worker 01M4RZG0R3KKZAYHX5VYS36QDZ [factory edgar, gimlet/BRM42220060/1253] (queued for 26 m 51 s)
32026-10-12T21:18:17.897Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-10-12T21:18:17.965Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-10-12T21:18:17.989Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-10-12T21:18:18.016Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-10-12T21:18:18.016Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-10-12T21:18:26.756Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-10-12T21:18:26.756Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-10-12T21:18:26.808Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-10-12T21:18:26.809Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-10-12T21:18:38.764Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-10-12T21:18:38.764Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-10-12T21:18:48.758Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-10-12T21:18:48.759Zstarting task 0: "setup"
162026-10-12T21:18:48.783Z++ uname -s
172026-10-12T21:18:48.783Z+ kern=SunOS
182026-10-12T21:18:48.783Z+ build_user=build
192026-10-12T21:18:48.783Z+ build_uid=12345
202026-10-12T21:18:48.783Z+ work_dir=/work
212026-10-12T21:18:48.784Z+ input_dir=/input
222026-10-12T21:18:48.784Z+ [[ 0 == 12345 ]]
232026-10-12T21:18:48.784Z+ case "$kern" in
242026-10-12T21:18:48.784Z+ groupadd -g 12345 build
252026-10-12T21:18:48.784Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-10-12T21:18:50.791Z+ zfs create -o mountpoint=/work rpool/work
272026-10-12T21:18:51.024Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-10-12T21:18:51.049Z+ home_fs=
292026-10-12T21:18:51.049Z+ [[ '' == autofs ]]
302026-10-12T21:18:51.049Z+ mkdir -p /home/build
312026-10-12T21:18:51.049Z+ chown build:build /home/build /work
322026-10-12T21:18:52.036Z+ chmod 0700 /home/build /work
332026-10-12T21:18:52.060Zprocess exited: duration 3284 ms, exit code 0
 
342026-10-12T21:18:52.110Zstarting task 1: "authentication"
352026-10-12T21:18:52.178Zprocess exited: duration 68 ms, exit code 0
 
362026-10-12T21:18:52.226Zstarting task 2: "build"
372026-10-12T21:18:52.252Z+ indir=/input
382026-10-12T21:18:52.252Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-10-12T21:18:52.252Z+ phddir=/work/phd-test
402026-10-12T21:18:52.252Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-10-12T21:18:52.277Z++ pilot local disk list -H -o type,disk
422026-10-12T21:18:52.277Z++ grep -v M.2
432026-10-12T21:18:52.277Z++ cut -f 2
442026-10-12T21:18:52.326Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC586d0 c9t0014EE81000BC57Cd0 c10t0014EE81000BC3CCd0 c11t0014EE81000BC478d0 c4t0014EE81000BC5BBd0 c3t0014EE81000BC247d0 c2t0014EE81000BC649d0 c6t0014EE81000BC634d0 c5t0014EE81000BC0B1d0
452026-10-12T21:18:54.891Z+ artifactdir=/phd-artifacts
462026-10-12T21:18:54.891Z+ banner Inputs
472026-10-12T21:18:54.920Z ###
482026-10-12T21:18:54.920Z # # # ##### # # ##### ####
492026-10-12T21:18:54.920Z # ## # # # # # # #
502026-10-12T21:18:54.920Z # # # # # # # # # ####
512026-10-12T21:18:54.920Z # # # # ##### # # # #
522026-10-12T21:18:54.920Z # # ## # # # # # #
532026-10-12T21:18:54.920Z ### # # # #### # ####
542026-10-12T21:18:54.920Z
552026-10-12T21:18:54.920Z+ find /input -ls
562026-10-12T21:18:54.920Z 34 1 drwxr-xr-x 3 root root 3 Oct 12 21:18 /input
572026-10-12T21:18:54.920Z 2 1 drwxr-xr-x 3 root root 3 Oct 12 21:18 /input/phd-build
582026-10-12T21:18:54.920Z 3 2 drwxr-xr-x 2 root root 8 Oct 12 21:18 /input/phd-build/out
592026-10-12T21:18:54.920Z 512 221070 -rw-r--r-- 1 root root 226304595 Oct 12 21:18 /input/phd-build/out/propolis-tests-debug.tar.gz
602026-10-12T21:18:54.920Z 130 188366 -rw-r--r-- 1 root root 192796706 Oct 12 21:18 /input/phd-build/out/phd-runner.tar.gz
612026-10-12T21:18:54.920Z 384 264352 -rw-r--r-- 1 root root 270657809 Oct 12 21:18 /input/phd-build/out/propolis-server-debug.tar.gz
622026-10-12T21:18:54.920Z 128 2 -rw-r--r-- 1 root root 2573 Oct 12 21:18 /input/phd-build/out/phd-run-with-args.sh
632026-10-12T21:18:54.920Z 256 1 -rw-r--r-- 1 root root 65 Oct 12 21:18 /input/phd-build/out/propolis-server-debug.sha256.txt
642026-10-12T21:18:54.921Z 129 1 -rw-r--r-- 1 root root 65 Oct 12 21:18 /input/phd-build/out/phd-runner.sha256.txt
652026-10-12T21:18:54.921Z+ rm -rf /work/phd-test
662026-10-12T21:18:54.921Z+ mkdir /work/phd-test
672026-10-12T21:18:54.921Z+ for p in $indir/$indir_suffix
682026-10-12T21:18:54.921Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-10-12T21:19:00.247ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-10-12T21:19:00.247Zx phd-runner, 737344752 bytes, 1440127 tape blocks
712026-10-12T21:19:00.247Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-10-12T21:19:00.271Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-10-12T21:19:05.063Z+ for f in $(tar tf "$p")
742026-10-12T21:19:05.063Z+ chmod +x /work/phd-test/phd-runner
752026-10-12T21:19:05.088Z+ for f in $(tar tf "$p")
762026-10-12T21:19:05.088Z+ chmod +x /work/phd-test/artifacts.toml
772026-10-12T21:19:05.088Z+ for p in $indir/$indir_suffix
782026-10-12T21:19:05.088Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-10-12T21:19:27.885ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-10-12T21:19:27.885Zx propolis-server, 1085291264 bytes, 2119710 tape blocks
812026-10-12T21:19:27.912Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-10-12T21:19:34.842Z+ for f in $(tar tf "$p")
832026-10-12T21:19:34.842Z+ chmod +x /work/phd-test/propolis-server
842026-10-12T21:19:34.867Z+ for p in $indir/$indir_suffix
852026-10-12T21:19:34.867Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-10-12T21:19:51.279ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-10-12T21:19:51.279Zx target/debug/deps/propolis-302acf9127bb46a8, 906108304 bytes, 1769743 tape blocks
882026-10-12T21:19:51.303Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-10-12T21:19:56.898Z+ for f in $(tar tf "$p")
902026-10-12T21:19:56.898Z+ chmod +x /work/phd-test/target/debug/deps/propolis-302acf9127bb46a8
912026-10-12T21:19:56.924Z+ ls /work/phd-test
922026-10-12T21:19:56.924Zartifacts.toml
932026-10-12T21:19:56.924Zphd-runner
942026-10-12T21:19:56.924Zpropolis-server
952026-10-12T21:19:56.924Ztarget
962026-10-12T21:19:56.924Z+ banner Setup
972026-10-12T21:19:56.924Z #####
982026-10-12T21:19:56.924Z# # ###### ##### # # #####
992026-10-12T21:19:56.924Z# # # # # # #
1002026-10-12T21:19:56.924Z ##### ##### # # # # #
1012026-10-12T21:19:56.924Z # # # # # #####
1022026-10-12T21:19:56.924Z# # # # # # #
1032026-10-12T21:19:56.924Z ##### ###### # #### #
1042026-10-12T21:19:56.925Z
1052026-10-12T21:19:56.925Z+ tmpdir=/tmp/propolis-phd
1062026-10-12T21:19:56.925Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-10-12T21:19:56.925Z+ mkdir /tmp/propolis-phd
1082026-10-12T21:19:56.925Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-10-12T21:19:57.370Z+ banner Tests
1102026-10-12T21:19:57.394Z#######
1112026-10-12T21:19:57.394Z # ###### #### ##### ####
1122026-10-12T21:19:57.394Z # # # # #
1132026-10-12T21:19:57.394Z # ##### #### # ####
1142026-10-12T21:19:57.394Z # # # # #
1152026-10-12T21:19:57.394Z # # # # # # #
1162026-10-12T21:19:57.394Z # ###### #### # ####
1172026-10-12T21:19:57.394Z
1182026-10-12T21:19:57.394Z+ runner=/work/phd-test/phd-runner
1192026-10-12T21:19:57.394Z+ artifacts=/work/phd-test/artifacts.toml
1202026-10-12T21:19:57.394Z+ propolis=/work/phd-test/propolis-server
1212026-10-12T21:19:57.394Z+ ls /work/phd-test/phd-runner
1222026-10-12T21:19:57.394Z/work/phd-test/phd-runner
1232026-10-12T21:19:57.394Z+ ls /work/phd-test/artifacts.toml
1242026-10-12T21:19:57.394Z/work/phd-test/artifacts.toml
1252026-10-12T21:19:57.394Z+ ls /work/phd-test/propolis-server
1262026-10-12T21:19:57.395Z/work/phd-test/propolis-server
1272026-10-12T21:19:57.395Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-10-12T21:19:57.395Z+ set +e
1292026-10-12T21:19:57.395Z+ RUST_BACKTRACE=1
1302026-10-12T21:19:57.395Z+ RUST_LOG=info,phd=debug
1312026-10-12T21:19:57.395Z+ ptime -m pfexec /work/phd-test/phd-runner --emit-bunyan run --propolis-server-cmd /work/phd-test/propolis-server --crucible-downstairs-commit auto --artifact-toml-path /work/phd-test/artifacts.toml --tmp-directory /tmp/propolis-phd --artifact-directory /phd-artifacts --include-filter phd_tests::migrate::from_base --base-propolis-branch master
1322026-10-12T21:19:57.395Z+ tee /tmp/phd-runner.log
1332026-10-12T21:19:57.588Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:57.562503149Z","target":"phd_runner","line":36,"file":"phd-tests/runner/src/main.rs","runner_args":"ProcessArgs { command: Run(RunOptions { propolis_server_cmd: \"/work/phd-test/propolis-server\", base_propolis_branch: Some(\"master\"), base_propolis_commit: None, base_propolis_cmd: None, crucible_downstairs_cmd: None, crucible_downstairs_commit: Some(Auto), tmp_directory: \"/tmp/propolis-phd\", artifact_directory: Some(\"/phd-artifacts\"), output_mode: TmpFile, default_guest_cpus: 2, default_guest_memory_mib: 512, artifact_toml_path: \"/work/phd-test/artifacts.toml\", default_guest_artifact: \"alpine\", default_bootrom_artifact: \"ovmf\", include_filter: [\"phd_tests::migrate::from_base\"], exclude_filter: [], max_buildomat_wait_secs: 1200, manual_stop_on_failure: false }), disable_ansi: false, emit_bunyan: true }"}
1342026-10-12T21:19:57.613Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:57.591580786Z","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: 246, tv_nsec: 809512993 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-10-12T21:19:57.613Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:57.591669654Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-10-12T21:19:57.613Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:57.59365681Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"bd62980710dd3d6d3524aa7f6617127942b75002"}
1372026-10-12T21:19:57.613Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:57.596790864Z","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/bd62980710dd3d6d3524aa7f6617127942b75002/crucible-nightly.sha256.txt","timeout":"600s"}
1382026-10-12T21:19:57.879Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:57.852119173Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-10-12T21:19:58.484Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.469458752Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/65886117ca3b32994b7a77f1436d55b716a1d5f8/propolis-server.sha256.txt","timeout":"600s"}
1402026-10-12T21:19:58.669Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.654550496Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-10-12T21:19:58.694Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.65532657Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-10-12T21:19:58.694Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.657864733Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-10-12T21:19:58.694Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.658812914Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-10-12T21:19:58.694Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.658849624Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-10-12T21:19:58.694Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.658881544Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-10-12T21:19:58.694Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.661921901Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
1472026-10-12T21:19:58.694Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.666582045Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
1482026-10-12T21:19:58.694Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:58.67027959Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
1492026-10-12T21:19:59.206Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:59.191149291Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::serial_history"}
1502026-10-12T21:19:59.231Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:19:59.203596041Z","target":"phd_framework::artifacts::store","line":614,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::serial_history"}
1512026-10-12T21:20:06.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:05.985964516Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::serial_history"}
1522026-10-12T21:20:06.010Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:05.986102088Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::serial_history"}
1532026-10-12T21:20:06.035Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:06.002488019Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 3.86M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
1542026-10-12T21:20:06.035Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:06.004866831Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-29396787-a836-4a53-b6a6-f35d19aa2022\"]","path":"phd_tests::migrate::from_base::serial_history"}
1552026-10-12T21:20:06.069Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:06.02814673Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-29396787-a836-4a53-b6a6-f35d19aa2022\", \"phd-artifacts/phd-clone-9c6e1033-398f-4f6f-b42b-acc4e9dd8d83\"]","path":"phd_tests::migrate::from_base::serial_history"}
1562026-10-12T21:20:06.105Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:06.045967919Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-9c6e1033-398f-4f6f-b42b-acc4e9dd8d83\"]","path":"phd_tests::migrate::from_base::serial_history"}
1572026-10-12T21:20:06.105Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:06.056881115Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-9c6e1033-398f-4f6f-b42b-acc4e9dd8d83 0B 25.3T 49.0M /phd-artifacts/phd-clone-9c6e1033-398f-4f6f-b42b-acc4e9dd8d83\n","path":"phd_tests::migrate::from_base::serial_history"}
1582026-10-12T21:20:06.105Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:06.060638513Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1592026-10-12T21:20:06.105Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:06.060764603Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_serial_history_base","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
1602026-10-12T21:20:06.105Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:06.060845497Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/c0d9344f91d563c7ab06bccfd2aae4b75c245ada57f0262eac2fd4a28094086e/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1612026-10-12T21:20:06.105Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:06.060919818Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/65886117ca3b32994b7a77f1436d55b716a1d5f8/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::serial_history"}
1622026-10-12T21:20:20.644Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:20.627742397Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","untar_path":"propolis-server","extracted_path":"/phd-artifacts/c0d9344f91d563c7ab06bccfd2aae4b75c245ada57f0262eac2fd4a28094086e/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
1632026-10-12T21:20:20.644Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:20.627831917Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::serial_history"}
1642026-10-12T21:20:45.710Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:45.692458094Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/c0d9344f91d563c7ab06bccfd2aae4b75c245ada57f0262eac2fd4a28094086e/propolis-server\"","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::serial_history"}
1652026-10-12T21:20:45.710Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:45.692588562Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
1662026-10-12T21:20:45.826Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 917","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:45.808929244Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
1672026-10-12T21:20:45.850Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:45.824372754Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1682026-10-12T21:20:45.851Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:45.8329292Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1692026-10-12T21:20:45.875Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:45.83577638Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":39774}
1702026-10-12T21:20:46.705Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.686803149Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-10-12T21:20:46.751Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.69266207Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 6da8da09-f204-4716-ac65-7bea91e6272d, name: \"phd-vm-6da8da09-f204-4716-ac65-7bea91e6272d\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: edcd5662-a4ea-4dc9-82c8-5b5dcbfa5b41, project_id: d38cc3a5-7d3e-44e2-b01b-4490009ffa3b, sled_id: 948cbcc0-5530-485e-b0aa-f4983a04887b, sled_serial: \"948cbcc0-5530-485e-b0aa-f4983a04887b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1722026-10-12T21:20:46.751Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.692884042Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1732026-10-12T21:20:46.751Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.692958583Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1742026-10-12T21:20:46.751Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.694936972Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":1,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1752026-10-12T21:20:46.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.696124959Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1762026-10-12T21:20:46.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.696203258Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d","timeout_duration":"300s","path":"phd_tests::migrate::from_base::serial_history"}
1772026-10-12T21:20:46.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.696773622Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
1782026-10-12T21:20:46.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.696831251Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1792026-10-12T21:20:46.751Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:46.697396485Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1802026-10-12T21:20:51.346Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.32905794Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4632,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1812026-10-12T21:20:51.346Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.32916851Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
1822026-10-12T21:20:51.371Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.332736419Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1832026-10-12T21:20:51.371Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.332804388Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1842026-10-12T21:20:51.371Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.332856688Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1852026-10-12T21:20:51.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.358279448Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":25,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1862026-10-12T21:20:51.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.358438841Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
1872026-10-12T21:20:51.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.358770902Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1882026-10-12T21:20:51.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.358837509Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1892026-10-12T21:20:51.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.358889437Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1902026-10-12T21:20:51.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.391595654Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1912026-10-12T21:20:51.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.391761459Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1922026-10-12T21:20:51.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.391840429Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4695}
1932026-10-12T21:20:51.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.394933826Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1942026-10-12T21:20:51.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.395008869Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1952026-10-12T21:20:51.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.413749745Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1962026-10-12T21:20:51.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.414007614Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1972026-10-12T21:20:51.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.414120289Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1982026-10-12T21:20:51.470Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.446820995Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
1992026-10-12T21:20:51.470Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.447119682Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2002026-10-12T21:20:51.470Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.447252044Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2012026-10-12T21:20:51.495Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.457468324Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2022026-10-12T21:20:51.495Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.457711005Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2032026-10-12T21:20:51.495Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.457830632Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2042026-10-12T21:20:51.520Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.49075348Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2052026-10-12T21:20:51.520Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.500035525Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2062026-10-12T21:20:51.520Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.500124023Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2072026-10-12T21:20:51.520Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.500172546Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
2082026-10-12T21:20:51.520Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.501773467Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","sha256":"None","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2092026-10-12T21:20:51.520Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.501837138Z","target":"phd_framework::artifacts::store","line":69,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2102026-10-12T21:20:51.520Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.501900048Z","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_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
2112026-10-12T21:20:51.520Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.501969109Z","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_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2122026-10-12T21:20:51.567Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 918","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.550053022Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
2132026-10-12T21:20:51.592Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.563627893Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":63}
2142026-10-12T21:20:51.592Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.563738763Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2152026-10-12T21:20:51.592Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.565245406Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"4af8c521-300c-4cec-93c1-eeec072c40b4","timeout_duration":"45s","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2162026-10-12T21:20:51.592Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.565330748Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2172026-10-12T21:20:51.592Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:51.56600048Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2182026-10-12T21:20:52.477Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:52.460078812Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 27c42844-d940-40b1-9468-e1ea33f92c1e, name: \"phd-vm-27c42844-d940-40b1-9468-e1ea33f92c1e\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: edcd5662-a4ea-4dc9-82c8-5b5dcbfa5b41, project_id: d38cc3a5-7d3e-44e2-b01b-4490009ffa3b, sled_id: 4d42531b-6b50-4cab-86b6-f420b131e6b3, sled_serial: \"4d42531b-6b50-4cab-86b6-f420b131e6b3\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2192026-10-12T21:20:52.502Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:52.460877579Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"4af8c521-300c-4cec-93c1-eeec072c40b4","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2202026-10-12T21:20:55.007Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:54.99031702Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7756}}"}
2212026-10-12T21:20:57.132Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.115174279Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2222026-10-12T21:20:57.132Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.115265633Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"4af8c521-300c-4cec-93c1-eeec072c40b4","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","elapsed_milliseconds":4654,"path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2232026-10-12T21:20:57.157Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.118382414Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2242026-10-12T21:20:57.157Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.12468557Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2252026-10-12T21:20:57.157Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.132098834Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2262026-10-12T21:20:57.157Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.132427318Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2272026-10-12T21:20:57.158Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.132619664Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10445}
2282026-10-12T21:20:57.158Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.134113131Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2292026-10-12T21:20:57.158Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.134247396Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2302026-10-12T21:20:57.158Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.134682372Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2312026-10-12T21:20:57.229Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.205356094Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":82,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2322026-10-12T21:20:57.257Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.205648569Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11381,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"6da8da09-f204-4716-ac65-7bea91e6272d"}
2332026-10-12T21:20:57.900Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.882331748Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2342026-10-12T21:20:57.995Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.977889916Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2352026-10-12T21:20:57.995Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:57.978035553Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-9c6e1033-398f-4f6f-b42b-acc4e9dd8d83\"]","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2362026-10-12T21:20:58.023Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.005510983Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2372026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.005596766Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-29396787-a836-4a53-b6a6-f35d19aa2022\"]","verb":"destroy","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2382026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.026602363Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":893,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2392026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.02679019Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","elapsed_milliseconds":6461,"vm":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","vm_id":"27c42844-d940-40b1-9468-e1ea33f92c1e","path":"phd_tests::migrate::from_base::serial_history","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2402026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.026873939Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"6da8da09-f204-4716-ac65-7bea91e6272d","elapsed_milliseconds":6462,"path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"27c42844-d940-40b1-9468-e1ea33f92c1e"}
2412026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.026934835Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":59364}
2422026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.027393065Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":893}
2432026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.027499588Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2442026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.027545154Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2452026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.027585942Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2462026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.027753209Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2472026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.027863509Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2482026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.027934374Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2492026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.028004517Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2502026-10-12T21:20:58.048Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.028084529Z","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"}
2512026-10-12T21:20:58.073Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.039065602Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2522026-10-12T21:20:58.074Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.039193515Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-af9dde2a-9dfa-44c6-be28-9d0eb7858da2\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-10-12T21:20:58.098Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.056921226Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-af9dde2a-9dfa-44c6-be28-9d0eb7858da2\", \"phd-artifacts/phd-clone-26644f85-804d-4308-9e9a-2d0ee9388cee\"]","verb":"clone","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-10-12T21:20:58.098Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.074994301Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-26644f85-804d-4308-9e9a-2d0ee9388cee\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-10-12T21:20:58.123Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.085460626Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-26644f85-804d-4308-9e9a-2d0ee9388cee 0B 25.3T 1.30G /phd-artifacts/phd-clone-26644f85-804d-4308-9e9a-2d0ee9388cee\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-10-12T21:20:58.123Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.086205862Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2572026-10-12T21:20:58.123Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.086278891Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2582026-10-12T21:20:58.123Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.086357179Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/c0d9344f91d563c7ab06bccfd2aae4b75c245ada57f0262eac2fd4a28094086e/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2592026-10-12T21:20:58.123Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.086427222Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/c0d9344f91d563c7ab06bccfd2aae4b75c245ada57f0262eac2fd4a28094086e/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2602026-10-12T21:20:58.123Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.086504489Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2612026-10-12T21:20:58.155Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 927","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.138086057Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2622026-10-12T21:20:58.180Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.15225156Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":65}
2632026-10-12T21:20:58.180Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.152391216Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2642026-10-12T21:20:58.180Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.153107146Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2652026-10-12T21:20:58.853Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.835476108Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2662026-10-12T21:20:58.899Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.836592459Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: cad3f3bb-f795-40bd-a4bc-52102cbd6314, name: \"phd-vm-cad3f3bb-f795-40bd-a4bc-52102cbd6314\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: c9cff454-4e25-457a-ba2d-35266cce7470, project_id: 245cc679-36d4-4e24-845f-2cb528bfd9f7, sled_id: 5eb8f4de-f8a7-4527-b19b-6272729fbdb1, sled_serial: \"5eb8f4de-f8a7-4527-b19b-6272729fbdb1\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2672026-10-12T21:20:58.899Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.836754296Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2682026-10-12T21:20:58.899Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.836813919Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2692026-10-12T21:20:58.899Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.837834578Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":1}
2702026-10-12T21:20:58.899Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.837921914Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2712026-10-12T21:20:58.899Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.837983551Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","vm":"migration_from_base","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-10-12T21:20:58.899Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.838032945Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2732026-10-12T21:20:58.899Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.838080476Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2742026-10-12T21:20:58.899Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:20:58.838131122Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2752026-10-12T21:21:03.365Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.346558781Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":4508}
2762026-10-12T21:21:03.365Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.346659533Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2772026-10-12T21:21:03.365Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.346855916Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2782026-10-12T21:21:03.365Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.346921661Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2792026-10-12T21:21:03.365Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.346982416Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2802026-10-12T21:21:03.390Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.365567755Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":18}
2812026-10-12T21:21:03.390Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.365716487Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2822026-10-12T21:21:03.390Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.365951283Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2832026-10-12T21:21:03.390Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.36601818Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2842026-10-12T21:21:03.390Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.366069889Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2852026-10-12T21:21:03.415Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.398217426Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":32}
2862026-10-12T21:21:03.440Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.398347242Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2872026-10-12T21:21:03.440Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.398434408Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4560}
2882026-10-12T21:21:03.440Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.398574474Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2892026-10-12T21:21:03.440Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.398637895Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2902026-10-12T21:21:03.440Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.409534155Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":10}
2912026-10-12T21:21:03.440Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.40966325Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2922026-10-12T21:21:03.440Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.409716731Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2932026-10-12T21:21:03.464Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.442988635Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":33}
2942026-10-12T21:21:03.464Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.443334322Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2952026-10-12T21:21:03.464Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.443469128Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2962026-10-12T21:21:03.489Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.454151433Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":10}
2972026-10-12T21:21:03.489Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.454426626Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2982026-10-12T21:21:03.489Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.454530794Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
2992026-10-12T21:21:03.513Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.476477158Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":21}
3002026-10-12T21:21:03.514Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.476679853Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3012026-10-12T21:21:03.514Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.476742692Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3022026-10-12T21:21:03.514Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.487380393Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":10}
3032026-10-12T21:21:03.514Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.487628705Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3042026-10-12T21:21:03.514Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.487689921Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3052026-10-12T21:21:03.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.520920664Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":33}
3062026-10-12T21:21:03.563Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.521254058Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3072026-10-12T21:21:03.563Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.521371321Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3082026-10-12T21:21:03.563Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.531925973Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":10}
3092026-10-12T21:21:03.563Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.532170528Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3102026-10-12T21:21:03.563Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.532277932Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3112026-10-12T21:21:03.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.554359745Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":22}
3122026-10-12T21:21:03.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.554692778Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3132026-10-12T21:21:03.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.554787909Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3142026-10-12T21:21:03.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.565193839Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":10}
3152026-10-12T21:21:03.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.565431941Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3162026-10-12T21:21:03.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.565535228Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3172026-10-12T21:21:03.617Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.598887031Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":33}
3182026-10-12T21:21:03.642Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.600145913Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3192026-10-12T21:21:03.642Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.600219432Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3202026-10-12T21:21:03.642Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.609905054Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":9}
3212026-10-12T21:21:03.642Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.610167944Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3222026-10-12T21:21:03.642Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.610274005Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3232026-10-12T21:21:03.667Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.63307857Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":22}
3242026-10-12T21:21:03.667Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.633282527Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3252026-10-12T21:21:03.667Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.633422192Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3262026-10-12T21:21:03.667Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.633514287Z","target":"phd_framework::test_vm","line":318,"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"}
3272026-10-12T21:21:03.667Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.633633424Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3282026-10-12T21:21:03.667Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.63373661Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3292026-10-12T21:21:03.667Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.633869983Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3302026-10-12T21:21:03.703Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.685812191Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3312026-10-12T21:21:03.728Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.698289342Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":64}
3322026-10-12T21:21:03.728Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.69837263Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3332026-10-12T21:21:03.728Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.698437183Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"c31f7454-36f9-488e-91d9-147dd77b9506","timeout_duration":"45s","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3342026-10-12T21:21:03.728Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.698501385Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3352026-10-12T21:21:03.728Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:03.699045569Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3362026-10-12T21:21:04.447Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:04.429768065Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 701d5ff2-f3b0-4266-9488-b72a5e3803fb, name: \"phd-vm-701d5ff2-f3b0-4266-9488-b72a5e3803fb\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: c9cff454-4e25-457a-ba2d-35266cce7470, project_id: 245cc679-36d4-4e24-845f-2cb528bfd9f7, sled_id: c40ad439-d058-4a88-ab42-59c9e4b052c1, sled_serial: \"c40ad439-d058-4a88-ab42-59c9e4b052c1\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3372026-10-12T21:21:04.472Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:04.429964599Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base","target":"migration_from_base_lifecycle_0","migration_id":"c31f7454-36f9-488e-91d9-147dd77b9506"}
3382026-10-12T21:21:06.968Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:06.950736683Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
3392026-10-12T21:21:07.345Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.327378534Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
3402026-10-12T21:21:07.345Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.327441825Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":2897,"source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base","target":"migration_from_base_lifecycle_0","migration_id":"c31f7454-36f9-488e-91d9-147dd77b9506"}
3412026-10-12T21:21:07.370Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.329436935Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3422026-10-12T21:21:07.370Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.32966554Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3432026-10-12T21:21:07.370Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.329734831Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo 3 > /proc/sys/vm/drop_caches","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3442026-10-12T21:21:07.370Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.331627737Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314"}
3452026-10-12T21:21:07.427Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.409781578Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":79}
3462026-10-12T21:21:07.452Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.410027025Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","elapsed_milliseconds":9257}
3472026-10-12T21:21:07.452Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.41029283Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":80}
3482026-10-12T21:21:07.452Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.410568534Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3492026-10-12T21:21:07.452Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.410668083Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3502026-10-12T21:21:07.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.442001223Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":31}
3512026-10-12T21:21:07.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.44226832Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3522026-10-12T21:21:07.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.442340156Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3532026-10-12T21:21:07.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.453104866Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":10}
3542026-10-12T21:21:07.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.453412591Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3552026-10-12T21:21:07.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.453491671Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3562026-10-12T21:21:07.505Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.487500896Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":34}
3572026-10-12T21:21:07.529Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.487773023Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3582026-10-12T21:21:07.529Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.487893331Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3592026-10-12T21:21:07.529Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.498602157Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":10}
3602026-10-12T21:21:07.529Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.498857712Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3612026-10-12T21:21:07.529Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.498964065Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3622026-10-12T21:21:07.553Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.532028372Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":33}
3632026-10-12T21:21:07.553Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.532186312Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3642026-10-12T21:21:07.553Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.532251235Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"mount | grep ' / type tmpfs '","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3652026-10-12T21:21:07.578Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.543884577Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":11}
3662026-10-12T21:21:07.578Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.54402812Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3672026-10-12T21:21:07.578Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.544092663Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3682026-10-12T21:21:07.602Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.578329187Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":34}
3692026-10-12T21:21:07.602Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.578576757Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3702026-10-12T21:21:07.602Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.578689151Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls /media/nvme0n1/boot","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3712026-10-12T21:21:07.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.589284581Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":10}
3722026-10-12T21:21:07.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.589560595Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3732026-10-12T21:21:07.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.589633434Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3742026-10-12T21:21:07.651Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.63361874Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":43}
3752026-10-12T21:21:07.676Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.633937786Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3762026-10-12T21:21:07.676Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.634044058Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3772026-10-12T21:21:07.676Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.644310543Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":10}
3782026-10-12T21:21:07.676Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.644467331Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3792026-10-12T21:21:07.676Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.644532695Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3802026-10-12T21:21:07.700Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.677385721Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":32}
3812026-10-12T21:21:07.700Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.677708013Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3822026-10-12T21:21:07.700Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.677781092Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"! dmesg | grep -q 'reset controller'","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3832026-10-12T21:21:07.725Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.68840182Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":10}
3842026-10-12T21:21:07.725Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.688629924Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3852026-10-12T21:21:07.725Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.688710737Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3862026-10-12T21:21:07.750Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.721443216Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":32}
3872026-10-12T21:21:07.750Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.72167207Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3882026-10-12T21:21:07.750Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.721744278Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3892026-10-12T21:21:07.775Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.732073522Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":10}
3902026-10-12T21:21:07.775Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.732413276Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3912026-10-12T21:21:07.775Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.732523215Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3922026-10-12T21:21:07.799Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.765269479Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":32}
3932026-10-12T21:21:07.799Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.765499737Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3942026-10-12T21:21:07.799Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.765784348Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3952026-10-12T21:21:07.799Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.765907151Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3962026-10-12T21:21:07.799Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.765932088Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8930}
3972026-10-12T21:21:07.800Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.766014495Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3982026-10-12T21:21:07.800Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:07.767134342Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
3992026-10-12T21:21:08.099Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.081027166Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
4002026-10-12T21:21:08.187Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.169552003Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
4012026-10-12T21:21:08.187Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.169663084Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-26644f85-804d-4308-9e9a-2d0ee9388cee\"]","verb":"destroy","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
4022026-10-12T21:21:08.213Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.195747841Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
4032026-10-12T21:21:08.213Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.195811722Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-af9dde2a-9dfa-44c6-be28-9d0eb7858da2\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb"}
4042026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.213845314Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":448}
4052026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.214028793Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0","vm_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":4515,"source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base"}
4062026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.214105027Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target_id":"701d5ff2-f3b0-4266-9488-b72a5e3803fb","elapsed_milliseconds":4515,"source_id":"cad3f3bb-f795-40bd-a4bc-52102cbd6314","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4072026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.214164581Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10186}
4082026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.214269871Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":448}
4092026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.214450213Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
4102026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.214559661Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
4112026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.214669991Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4122026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.214876593Z","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"}
4132026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.214988917Z","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"}
4142026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.215057948Z","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"}
4152026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.215127079Z","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"}
4162026-10-12T21:21:08.238Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.21520651Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4172026-10-12T21:21:08.263Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.22722284Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-10-12T21:21:08.263Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.227379327Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-b2bfc393-761b-4c59-a146-1839afd3d58c\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4192026-10-12T21:21:08.287Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.246911184Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-b2bfc393-761b-4c59-a146-1839afd3d58c\", \"phd-artifacts/phd-clone-fb775efb-c482-4d74-897c-a3a250ea9a7a\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4202026-10-12T21:21:08.287Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.264427744Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-fb775efb-c482-4d74-897c-a3a250ea9a7a\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4212026-10-12T21:21:08.312Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.276690452Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-fb775efb-c482-4d74-897c-a3a250ea9a7a 0B 25.3T 1.30G /phd-artifacts/phd-clone-fb775efb-c482-4d74-897c-a3a250ea9a7a\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4222026-10-12T21:21:08.312Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.277357419Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4232026-10-12T21:21:08.312Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.277432301Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4242026-10-12T21:21:08.312Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.277514477Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/c0d9344f91d563c7ab06bccfd2aae4b75c245ada57f0262eac2fd4a28094086e/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4252026-10-12T21:21:08.312Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.277580883Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/c0d9344f91d563c7ab06bccfd2aae4b75c245ada57f0262eac2fd4a28094086e/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4262026-10-12T21:21:08.312Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.277677216Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4272026-10-12T21:21:08.347Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 937","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.329755338Z","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"}
4282026-10-12T21:21:08.371Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.344091155Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":66}
4292026-10-12T21:21:08.372Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.344195723Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4302026-10-12T21:21:08.372Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.344904971Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4312026-10-12T21:21:08.955Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.937353224Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
4322026-10-12T21:21:09.002Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.9382779Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: b235aa81-80f7-4f5b-beb6-55ea58baf5b8, name: \"phd-vm-b235aa81-80f7-4f5b-beb6-55ea58baf5b8\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: d0a0deb1-cd1f-4f1d-bfeb-a4bdb0d31b7f, project_id: 7692d34c-54b9-4fe5-aa51-b6d2f9557fb7, sled_id: 099f500f-baaa-4b43-9f7c-e2a9db11d600, sled_serial: \"099f500f-baaa-4b43-9f7c-e2a9db11d600\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4332026-10-12T21:21:09.002Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.938433877Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4342026-10-12T21:21:09.002Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.93849378Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4352026-10-12T21:21:09.002Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.939526132Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":1}
4362026-10-12T21:21:09.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.939613588Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4372026-10-12T21:21:09.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.939673662Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","timeout_duration":"300s","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4382026-10-12T21:21:09.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.939732153Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4392026-10-12T21:21:09.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.939779834Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4402026-10-12T21:21:09.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:08.939831302Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4412026-10-12T21:21:13.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.506999891Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":4567}
4422026-10-12T21:21:13.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.507103338Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4432026-10-12T21:21:13.550Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.507296244Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4442026-10-12T21:21:13.550Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.507354455Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4452026-10-12T21:21:13.550Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.507401154Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4462026-10-12T21:21:13.550Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.526394467Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":18}
4472026-10-12T21:21:13.550Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.526482475Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4482026-10-12T21:21:13.550Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.526732409Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4492026-10-12T21:21:13.550Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.526807863Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4502026-10-12T21:21:13.550Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.52687476Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4512026-10-12T21:21:13.577Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.559028689Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":32}
4522026-10-12T21:21:13.577Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.559136223Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-10-12T21:21:13.601Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.559180117Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4619}
4542026-10-12T21:21:13.601Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.559373244Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4552026-10-12T21:21:13.602Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.559432967Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4562026-10-12T21:21:13.602Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.570060428Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":10}
4572026-10-12T21:21:13.602Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.570196777Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4582026-10-12T21:21:13.602Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.570251071Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4592026-10-12T21:21:13.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.603271374Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":33}
4602026-10-12T21:21:13.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.603414987Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4612026-10-12T21:21:13.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.603470342Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4622026-10-12T21:21:13.651Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.613984237Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":10}
4632026-10-12T21:21:13.651Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.614167035Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4642026-10-12T21:21:13.651Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.614245073Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4652026-10-12T21:21:13.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.647130681Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":32}
4662026-10-12T21:21:13.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.647321593Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4672026-10-12T21:21:13.675Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.647402257Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4682026-10-12T21:21:13.700Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.658014499Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":10}
4692026-10-12T21:21:13.700Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.658195943Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4702026-10-12T21:21:13.700Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.658274072Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4712026-10-12T21:21:13.724Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.691059619Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":32}
4722026-10-12T21:21:13.724Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.691245092Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4732026-10-12T21:21:13.724Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.691324252Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4742026-10-12T21:21:13.724Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.702199765Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":10}
4752026-10-12T21:21:13.724Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.702419141Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4762026-10-12T21:21:13.724Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.702482251Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4772026-10-12T21:21:13.754Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.736011443Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":33}
4782026-10-12T21:21:13.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.736276477Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4792026-10-12T21:21:13.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.736340088Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4802026-10-12T21:21:13.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.746922812Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":10}
4812026-10-12T21:21:13.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.747169601Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4822026-10-12T21:21:13.778Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.747274791Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4832026-10-12T21:21:13.805Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.780430253Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":33}
4842026-10-12T21:21:13.805Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.780750872Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4852026-10-12T21:21:13.805Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.780869207Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4862026-10-12T21:21:13.829Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.791430933Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":10}
4872026-10-12T21:21:13.829Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.791678844Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4882026-10-12T21:21:13.829Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.791788422Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
4892026-10-12T21:21:13.856Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.824993908Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":33}
4902026-10-12T21:21:13.856Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.82518968Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4912026-10-12T21:21:13.856Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.825331679Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4922026-10-12T21:21:13.856Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.825439254Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4932026-10-12T21:21:13.856Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.825561065Z","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"}
4942026-10-12T21:21:13.856Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.825616731Z","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:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4952026-10-12T21:21:13.857Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.825689509Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4962026-10-12T21:21:13.893Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.875602727Z","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"}
4972026-10-12T21:21:13.918Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.889112364Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":63}
4982026-10-12T21:21:13.919Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.889218325Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
4992026-10-12T21:21:13.919Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.889293919Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"7e8f604c-7a75-4e4d-9a64-4eee6c13e559","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
5002026-10-12T21:21:13.919Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.889359593Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
5012026-10-12T21:21:13.919Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:13.89003156Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
5022026-10-12T21:21:14.377Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:14.358894168Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 0197a0e2-afc7-4c9c-87e2-ab3807ae63ab, name: \"phd-vm-0197a0e2-afc7-4c9c-87e2-ab3807ae63ab\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: d0a0deb1-cd1f-4f1d-bfeb-a4bdb0d31b7f, project_id: 7692d34c-54b9-4fe5-aa51-b6d2f9557fb7, sled_id: 31425707-1743-4264-a4c4-9db8cc5134df, sled_serial: \"31425707-1743-4264-a4c4-9db8cc5134df\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
5032026-10-12T21:21:14.401Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:14.359087596Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","migration_id":"7e8f604c-7a75-4e4d-9a64-4eee6c13e559","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
5042026-10-12T21:21:16.880Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:16.861588607Z","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}}"}
5052026-10-12T21:21:18.718Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.700354791Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
5062026-10-12T21:21:18.718Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.700430725Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","migration_id":"7e8f604c-7a75-4e4d-9a64-4eee6c13e559","elapsed_milliseconds":4341,"source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
5072026-10-12T21:21:18.743Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.703278666Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
5082026-10-12T21:21:18.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.703602842Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab"}
5092026-10-12T21:21:18.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.703678205Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab"}
5102026-10-12T21:21:18.743Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.705033069Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8"}
5112026-10-12T21:21:18.805Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.786743549Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":83}
5122026-10-12T21:21:18.829Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.787005677Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","elapsed_milliseconds":10442}
5132026-10-12T21:21:18.829Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.787153738Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","elapsed_milliseconds":83}
5142026-10-12T21:21:18.829Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.787445002Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab"}
5152026-10-12T21:21:18.829Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.787557656Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab"}
5162026-10-12T21:21:18.853Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.81640968Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","elapsed_milliseconds":28}
5172026-10-12T21:21:18.853Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.816548483Z","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"}
5182026-10-12T21:21:18.853Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.816691756Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5192026-10-12T21:21:18.853Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.816791906Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5202026-10-12T21:21:18.853Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.816919158Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/c0d9344f91d563c7ab06bccfd2aae4b75c245ada57f0262eac2fd4a28094086e/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5212026-10-12T21:21:18.853Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.817047722Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/c0d9344f91d563c7ab06bccfd2aae4b75c245ada57f0262eac2fd4a28094086e/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5222026-10-12T21:21:18.853Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.817161528Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5232026-10-12T21:21:18.887Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 940","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.869080157Z","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"}
5242026-10-12T21:21:18.911Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.886755637Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":69}
5252026-10-12T21:21:18.911Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.886881156Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1"}
5262026-10-12T21:21:18.911Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.886976517Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"15e113c9-1982-4cce-b433-80f9d2571abd","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1"}
5272026-10-12T21:21:18.911Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.887055958Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1"}
5282026-10-12T21:21:18.911Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:18.887753583Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1"}
5292026-10-12T21:21:19.313Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:19.295066074Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 05b8a7c9-3675-4664-bb44-eea3c3cf7cf3, name: \"phd-vm-05b8a7c9-3675-4664-bb44-eea3c3cf7cf3\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: d0a0deb1-cd1f-4f1d-bfeb-a4bdb0d31b7f, project_id: 7692d34c-54b9-4fe5-aa51-b6d2f9557fb7, sled_id: 10954ecf-1435-4cdf-8166-12d7860ea7bb, sled_serial: \"10954ecf-1435-4cdf-8166-12d7860ea7bb\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1"}
5302026-10-12T21:21:19.337Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:19.295254753Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","migration_id":"15e113c9-1982-4cce-b433-80f9d2571abd","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1"}
5312026-10-12T21:21:21.803Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:21.78501619Z","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}}"}
5322026-10-12T21:21:23.661Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.642842936Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1"}
5332026-10-12T21:21:23.661Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.642927958Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","migration_id":"15e113c9-1982-4cce-b433-80f9d2571abd","elapsed_milliseconds":4347,"source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1"}
5342026-10-12T21:21:23.687Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.645638087Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab"}
5352026-10-12T21:21:23.687Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.645916336Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3"}
5362026-10-12T21:21:23.688Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.645995676Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3"}
5372026-10-12T21:21:23.688Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.647347124Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab"}
5382026-10-12T21:21:23.759Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.740915443Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","elapsed_milliseconds":94}
5392026-10-12T21:21:23.785Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.741180597Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","vm_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","elapsed_milliseconds":9851,"target":"migration_from_base_and_back_lifecycle_0","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","vm":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back"}
5402026-10-12T21:21:23.785Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.741320222Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"b235aa81-80f7-4f5b-beb6-55ea58baf5b8","target_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","elapsed_milliseconds":9851,"source":"migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0"}
5412026-10-12T21:21:23.865Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.847315589Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","elapsed_milliseconds":201}
5422026-10-12T21:21:23.890Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.847631118Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3"}
5432026-10-12T21:21:23.890Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.847761747Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3"}
5442026-10-12T21:21:23.914Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.879802358Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","elapsed_milliseconds":32}
5452026-10-12T21:21:23.914Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.879952493Z","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"}
5462026-10-12T21:21:23.914Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.88006174Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5472026-10-12T21:21:23.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.880126544Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5482026-10-12T21:21:23.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.880209742Z","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"}
5492026-10-12T21:21:23.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.880275837Z","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:9006","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5502026-10-12T21:21:23.914Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.88035613Z","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"}
5512026-10-12T21:21:23.952Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 942","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.934377423Z","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"}
5522026-10-12T21:21:23.977Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.948186469Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":68}
5532026-10-12T21:21:23.977Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.948291869Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2"}
5542026-10-12T21:21:23.977Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.948371821Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"cf56d57f-1682-49b4-8dc1-b1f47912f1a7","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2"}
5552026-10-12T21:21:23.977Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.948451442Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2"}
5562026-10-12T21:21:23.977Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:23.949103782Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2"}
5572026-10-12T21:21:24.621Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:24.602479784Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: d133f725-f0c6-4cd3-9d70-106f35a9d77f, name: \"phd-vm-d133f725-f0c6-4cd3-9d70-106f35a9d77f\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: d0a0deb1-cd1f-4f1d-bfeb-a4bdb0d31b7f, project_id: 7692d34c-54b9-4fe5-aa51-b6d2f9557fb7, sled_id: 8e2f22fc-9be5-4451-9d90-8a8920239131, sled_serial: \"8e2f22fc-9be5-4451-9d90-8a8920239131\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2"}
5582026-10-12T21:21:24.621Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:24.602669114Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","migration_id":"cf56d57f-1682-49b4-8dc1-b1f47912f1a7","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2"}
5592026-10-12T21:21:27.150Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.131964566Z","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}}"}
5602026-10-12T21:21:27.189Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.1716028Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2"}
5612026-10-12T21:21:27.189Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.171664948Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","migration_id":"cf56d57f-1682-49b4-8dc1-b1f47912f1a7","elapsed_milliseconds":2568,"source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2"}
5622026-10-12T21:21:27.214Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.173828839Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3"}
5632026-10-12T21:21:27.214Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.174059227Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5642026-10-12T21:21:27.214Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.174126765Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5652026-10-12T21:21:27.214Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.175373221Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3"}
5662026-10-12T21:21:27.273Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.254966429Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","elapsed_milliseconds":80}
5672026-10-12T21:21:27.297Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.255262585Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","vm_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","elapsed_milliseconds":8367,"target":"migration_from_base_and_back_lifecycle_1","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","vm":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0"}
5682026-10-12T21:21:27.297Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.255401439Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"0197a0e2-afc7-4c9c-87e2-ab3807ae63ab","target_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","elapsed_milliseconds":8367,"source":"migration_from_base_and_back_lifecycle_0","target":"migration_from_base_and_back_lifecycle_1"}
5692026-10-12T21:21:27.298Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.255488775Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","elapsed_milliseconds":81}
5702026-10-12T21:21:27.298Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.255809444Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5712026-10-12T21:21:27.298Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.25592329Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5722026-10-12T21:21:27.323Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.287303488Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","elapsed_milliseconds":31}
5732026-10-12T21:21:27.323Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.287502296Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5742026-10-12T21:21:27.323Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.287771728Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5752026-10-12T21:21:27.323Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.28790967Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5762026-10-12T21:21:27.323Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.287961067Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":18349}
5772026-10-12T21:21:27.323Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.288014639Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5782026-10-12T21:21:27.323Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:27.289457671Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5792026-10-12T21:21:28.038Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.019566812Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5802026-10-12T21:21:28.126Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.108093008Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5812026-10-12T21:21:28.126Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.108203487Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-fb775efb-c482-4d74-897c-a3a250ea9a7a\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5822026-10-12T21:21:28.154Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.137260076Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5832026-10-12T21:21:28.179Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.137331993Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-b2bfc393-761b-4c59-a146-1839afd3d58c\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f"}
5842026-10-12T21:21:28.179Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.160909825Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","elapsed_milliseconds":873}
5852026-10-12T21:21:28.179Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.161202242Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","vm_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","elapsed_milliseconds":4211,"target":"migration_from_base_and_back_lifecycle_2","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","vm":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1"}
5862026-10-12T21:21:28.179Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.161398177Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":873}
5872026-10-12T21:21:28.179Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.161422563Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"05b8a7c9-3675-4664-bb44-eea3c3cf7cf3","target_id":"d133f725-f0c6-4cd3-9d70-106f35a9d77f","elapsed_milliseconds":4212,"source":"migration_from_base_and_back_lifecycle_1","target":"migration_from_base_and_back_lifecycle_2"}
5882026-10-12T21:21:28.179Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.161515269Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":19945}
5892026-10-12T21:21:28.179Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.161577067Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5902026-10-12T21:21:28.179Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.161661517Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5912026-10-12T21:21:28.204Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 89.50s
5922026-10-12T21:21:28.204Z
5932026-10-12T21:21:28.204Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220060","pid":912,"time":"2026-10-12T21:21:28.163327522Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5942026-10-12T21:21:28.322Z
5952026-10-12T21:21:28.322Zreal 1:30.790601011
5962026-10-12T21:21:28.322Zuser 50.984692596
5972026-10-12T21:21:28.322Zsys 21.944888000
5982026-10-12T21:21:28.323Ztrap 0.007481483
5992026-10-12T21:21:28.323Ztflt 0.003345392
6002026-10-12T21:21:28.347Zdflt 0.001531574
6012026-10-12T21:21:28.347Zkflt 0.000000000
6022026-10-12T21:21:28.347Zlock 3:32:06.564668162
6032026-10-12T21:21:28.347Zslp 4:18.667339876
6042026-10-12T21:21:28.347Zlat 2.036896205
6052026-10-12T21:21:28.347Zstop 51.993993791
6062026-10-12T21:21:28.347Z+ failcount=0
6072026-10-12T21:21:28.347Z+ set -e
6082026-10-12T21:21:28.347Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
6092026-10-12T21:21:28.373ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
6102026-10-12T21:21:28.373Za ./ 0K
6112026-10-12T21:21:28.373Za ./phd_tests::migrate::from_base::serial_history/ 0K
6122026-10-12T21:21:28.373Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 159K
6132026-10-12T21:21:28.373Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
6142026-10-12T21:21:28.373Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
6152026-10-12T21:21:28.373Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 165K
6162026-10-12T21:21:28.373Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
6172026-10-12T21:21:28.373Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
6182026-10-12T21:21:28.373Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 158K
6192026-10-12T21:21:28.373Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
6202026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
6212026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 164K
6222026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
6232026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
6242026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 158K
6252026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
6262026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
6272026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 269K
6282026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
6292026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 269K
6302026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
6312026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 165K
6322026-10-12T21:21:28.374Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
6332026-10-12T21:21:28.374Z+ exitcode=0
6342026-10-12T21:21:28.374Z+ '[' 0 -eq 0 ']'
6352026-10-12T21:21:28.374Z+ echo
6362026-10-12T21:21:28.374Z
6372026-10-12T21:21:28.374Z+ echo 'ALL TESTS PASSED'
6382026-10-12T21:21:28.374ZALL TESTS PASSED
6392026-10-12T21:21:28.374Z+ echo
6402026-10-12T21:21:28.374Z
6412026-10-12T21:21:28.374Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6422026-10-12T21:21:28.374Z+ read
6432026-10-12T21:21:28.374Z+ exit 0
6442026-10-12T21:21:28.374Zprocess exited: duration 156127 ms, exit code 0
 
6452026-10-12T21:21:28.453Zfound 2 output files
6462026-10-12T21:21:28.453Zuploading: /tmp/phd-runner.log (202746 bytes)
6472026-10-12T21:21:29.616Zuploaded: /tmp/phd-runner.log
6482026-10-12T21:21:29.616Zuploading: /tmp/phd-tmp-files.tar.gz (133944 bytes)
6492026-10-12T21:21:30.798Zuploaded: /tmp/phd-tmp-files.tar.gz