01M6PV7B1BFTS1D1BCY86E7PT0: phd-run-migrate-from-base

BasicConfig {
    output_rules: [
        "/tmp/phd-runner.log",
        "/tmp/phd-tmp-files.tar.gz",
    ],
    rust_toolchain: None,
    target: Some(
        "lab-3.0-gimlet",
    ),
    access_repos: [],
    publish: [],
    skip_clone: true,
}

Buildomat Job: 01M6PV87AY7J7TTH526EJK5GEE

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-11-05T22:06:05.055Zjob dependencies complete; ready to run (waiting for 12 m 20 s)
22026-11-06T00:26:19.989Zjob assigned to worker 01M6Q3SFH6S0YSXMJT5GS4K2XT [factory edgar, gimlet/BRM42220010/1956] (queued for 2 h 20 m 14 s)
32026-11-06T00:26:21.220Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-11-06T00:26:21.265Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-11-06T00:26:21.265Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-11-06T00:26:21.324Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-11-06T00:26:21.354Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-11-06T00:26:31.147Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-11-06T00:26:31.147Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-11-06T00:26:31.201Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-11-06T00:26:31.201Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-11-06T00:27:11.994Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-11-06T00:27:11.994Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-11-06T00:28:53.806Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-11-06T00:28:53.806Zstarting task 0: "setup"
162026-11-06T00:28:53.831Z++ uname -s
172026-11-06T00:28:53.831Z+ kern=SunOS
182026-11-06T00:28:53.831Z+ build_user=build
192026-11-06T00:28:53.831Z+ build_uid=12345
202026-11-06T00:28:53.831Z+ work_dir=/work
212026-11-06T00:28:53.831Z+ input_dir=/input
222026-11-06T00:28:53.831Z+ [[ 0 == 12345 ]]
232026-11-06T00:28:53.831Z+ case "$kern" in
242026-11-06T00:28:53.831Z+ groupadd -g 12345 build
252026-11-06T00:28:53.831Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-11-06T00:28:55.839Z+ zfs create -o mountpoint=/work rpool/work
272026-11-06T00:28:55.869Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-11-06T00:28:55.893Z+ home_fs=
292026-11-06T00:28:55.893Z+ [[ '' == autofs ]]
302026-11-06T00:28:55.893Z+ mkdir -p /home/build
312026-11-06T00:28:55.893Z+ chown build:build /home/build /work
322026-11-06T00:28:57.882Z+ chmod 0700 /home/build /work
332026-11-06T00:28:57.906Zprocess exited: duration 4080 ms, exit code 0
 
342026-11-06T00:28:57.956Zstarting task 1: "authentication"
352026-11-06T00:28:58.025Zprocess exited: duration 68 ms, exit code 0
 
362026-11-06T00:28:58.079Zstarting task 2: "build"
372026-11-06T00:28:58.104Z+ indir=/input
382026-11-06T00:28:58.104Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-11-06T00:28:58.104Z+ phddir=/work/phd-test
402026-11-06T00:28:58.104Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-11-06T00:28:58.130Z++ pilot local disk list -H -o type,disk
422026-11-06T00:28:58.130Z++ grep -v M.2
432026-11-06T00:28:58.130Z++ cut -f 2
442026-11-06T00:28:58.203Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
452026-11-06T00:29:00.706Z+ artifactdir=/phd-artifacts
462026-11-06T00:29:00.706Z+ banner Inputs
472026-11-06T00:29:00.732Z ###
482026-11-06T00:29:00.732Z # # # ##### # # ##### ####
492026-11-06T00:29:00.732Z # ## # # # # # # #
502026-11-06T00:29:00.732Z # # # # # # # # # ####
512026-11-06T00:29:00.732Z # # # # ##### # # # #
522026-11-06T00:29:00.732Z # # ## # # # # # #
532026-11-06T00:29:00.732Z ### # # # #### # ####
542026-11-06T00:29:00.732Z
552026-11-06T00:29:00.732Z+ find /input -ls
562026-11-06T00:29:00.732Z 34 1 drwxr-xr-x 3 root root 3 Nov 6 00:26 /input
572026-11-06T00:29:00.732Z 2 1 drwxr-xr-x 3 root root 3 Nov 6 00:26 /input/phd-build
582026-11-06T00:29:00.732Z 3 2 drwxr-xr-x 2 root root 8 Nov 6 00:27 /input/phd-build/out
592026-11-06T00:29:00.732Z 128 2 -rw-r--r-- 1 root root 2573 Nov 6 00:26 /input/phd-build/out/phd-run-with-args.sh
602026-11-06T00:29:00.732Z 129 1 -rw-r--r-- 1 root root 65 Nov 6 00:26 /input/phd-build/out/phd-runner.sha256.txt
612026-11-06T00:29:00.732Z 130 192185 -rw-r--r-- 1 root root 196670435 Nov 6 00:26 /input/phd-build/out/phd-runner.tar.gz
622026-11-06T00:29:00.732Z 512 217293 -rw-r--r-- 1 root root 222365652 Nov 6 00:28 /input/phd-build/out/propolis-tests-debug.tar.gz
632026-11-06T00:29:00.732Z 256 1 -rw-r--r-- 1 root root 65 Nov 6 00:26 /input/phd-build/out/propolis-server-debug.sha256.txt
642026-11-06T00:29:00.732Z 384 264025 -rw-r--r-- 1 root root 270187362 Nov 6 00:27 /input/phd-build/out/propolis-server-debug.tar.gz
652026-11-06T00:29:00.732Z+ rm -rf /work/phd-test
662026-11-06T00:29:00.732Z+ mkdir /work/phd-test
672026-11-06T00:29:00.732Z+ for p in $indir/$indir_suffix
682026-11-06T00:29:00.732Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-11-06T00:29:15.373ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-11-06T00:29:15.373Zx phd-runner, 734739232 bytes, 1435038 tape blocks
712026-11-06T00:29:15.373Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-11-06T00:29:15.400Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-11-06T00:29:18.427Z+ for f in $(tar tf "$p")
742026-11-06T00:29:18.427Z+ chmod +x /work/phd-test/phd-runner
752026-11-06T00:29:18.453Z+ for f in $(tar tf "$p")
762026-11-06T00:29:18.453Z+ chmod +x /work/phd-test/artifacts.toml
772026-11-06T00:29:18.453Z+ for p in $indir/$indir_suffix
782026-11-06T00:29:18.453Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-11-06T00:29:31.581ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-11-06T00:29:31.581Zx propolis-server, 1051154544 bytes, 2053037 tape blocks
812026-11-06T00:29:31.630Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-11-06T00:29:35.807Z+ for f in $(tar tf "$p")
832026-11-06T00:29:35.807Z+ chmod +x /work/phd-test/propolis-server
842026-11-06T00:29:35.831Z+ for p in $indir/$indir_suffix
852026-11-06T00:29:35.831Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-11-06T00:29:53.524ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-11-06T00:29:53.524Zx target/debug/deps/propolis-addd1e09e00f8ec1, 866717344 bytes, 1692808 tape blocks
882026-11-06T00:29:53.548Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-11-06T00:29:56.952Z+ for f in $(tar tf "$p")
902026-11-06T00:29:56.952Z+ chmod +x /work/phd-test/target/debug/deps/propolis-addd1e09e00f8ec1
912026-11-06T00:29:56.977Z+ ls /work/phd-test
922026-11-06T00:29:56.977Zartifacts.toml
932026-11-06T00:29:56.977Zphd-runner
942026-11-06T00:29:56.977Zpropolis-server
952026-11-06T00:29:56.977Ztarget
962026-11-06T00:29:56.977Z+ banner Setup
972026-11-06T00:29:56.977Z #####
982026-11-06T00:29:56.977Z# # ###### ##### # # #####
992026-11-06T00:29:56.977Z# # # # # # #
1002026-11-06T00:29:56.977Z ##### ##### # # # # #
1012026-11-06T00:29:56.977Z # # # # # #####
1022026-11-06T00:29:56.977Z# # # # # # #
1032026-11-06T00:29:56.977Z ##### ###### # #### #
1042026-11-06T00:29:56.977Z
1052026-11-06T00:29:56.977Z+ tmpdir=/tmp/propolis-phd
1062026-11-06T00:29:56.977Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-11-06T00:29:56.977Z+ mkdir /tmp/propolis-phd
1082026-11-06T00:29:56.977Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-11-06T00:29:57.390Z+ banner Tests
1102026-11-06T00:29:57.414Z#######
1112026-11-06T00:29:57.414Z # ###### #### ##### ####
1122026-11-06T00:29:57.414Z # # # # #
1132026-11-06T00:29:57.414Z # ##### #### # ####
1142026-11-06T00:29:57.414Z # # # # #
1152026-11-06T00:29:57.415Z # # # # # # #
1162026-11-06T00:29:57.415Z # ###### #### # ####
1172026-11-06T00:29:57.415Z
1182026-11-06T00:29:57.415Z+ runner=/work/phd-test/phd-runner
1192026-11-06T00:29:57.415Z+ artifacts=/work/phd-test/artifacts.toml
1202026-11-06T00:29:57.415Z+ propolis=/work/phd-test/propolis-server
1212026-11-06T00:29:57.415Z+ ls /work/phd-test/phd-runner
1222026-11-06T00:29:57.415Z/work/phd-test/phd-runner
1232026-11-06T00:29:57.415Z+ ls /work/phd-test/artifacts.toml
1242026-11-06T00:29:57.415Z/work/phd-test/artifacts.toml
1252026-11-06T00:29:57.416Z+ ls /work/phd-test/propolis-server
1262026-11-06T00:29:57.416Z/work/phd-test/propolis-server
1272026-11-06T00:29:57.416Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-11-06T00:29:57.416Z+ set +e
1292026-11-06T00:29:57.416Z+ RUST_BACKTRACE=1
1302026-11-06T00:29:57.416Z+ RUST_LOG=info,phd=debug
1312026-11-06T00:29:57.416Z+ 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-11-06T00:29:57.416Z+ tee /tmp/phd-runner.log
1332026-11-06T00:29:57.618Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:29:57.582410821Z","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-11-06T00:29:57.645Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:29:57.61426742Z","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: 368, tv_nsec: 50375008 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-11-06T00:29:57.646Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:29:57.614881572Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-11-06T00:29:57.646Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:29:57.61583715Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"bd62980710dd3d6d3524aa7f6617127942b75002"}
1372026-11-06T00:29:57.646Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:29:57.620752562Z","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-11-06T00:30:00.326Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:00.303613923Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-11-06T00:30:00.945Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:00.922532538Z","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/12b00ba88d088e0c61b2d4d26f765fc83f6a76b8/propolis-server.sha256.txt","timeout":"600s"}
1402026-11-06T00:30:01.143Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:01.119775009Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-11-06T00:30:01.176Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:01.120324641Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-11-06T00:30:01.176Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:01.121441725Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-11-06T00:30:01.176Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:01.122571352Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-11-06T00:30:01.176Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:01.122609875Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-11-06T00:30:01.176Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:01.122643339Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-11-06T00:30:01.176Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:01.123944731Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
1472026-11-06T00:30:01.176Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:01.125996604Z","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-11-06T00:30:01.177Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:01.129029784Z","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-11-06T00:30:05.664Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:05.640241834Z","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-11-06T00:30:05.689Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:05.65097677Z","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-11-06T00:30:36.201Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.154347871Z","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-11-06T00:30:36.201Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.154453088Z","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::serial_history"}
1532026-11-06T00:30:36.201Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.166995261Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 3.44M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
1542026-11-06T00:30:36.201Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.168804112Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-e2f0a935-5e44-40a9-a541-88e52bace388\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::serial_history"}
1552026-11-06T00:30:36.225Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.189294773Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-e2f0a935-5e44-40a9-a541-88e52bace388\", \"phd-artifacts/phd-clone-b0be9164-c4e0-44a0-bfbe-06c9c88caa97\"]","verb":"clone","path":"phd_tests::migrate::from_base::serial_history"}
1562026-11-06T00:30:36.250Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.203133647Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-b0be9164-c4e0-44a0-bfbe-06c9c88caa97\"]","path":"phd_tests::migrate::from_base::serial_history"}
1572026-11-06T00:30:36.250Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.212536859Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-b0be9164-c4e0-44a0-bfbe-06c9c88caa97 0B 25.3T 49.0M /phd-artifacts/phd-clone-b0be9164-c4e0-44a0-bfbe-06c9c88caa97\n","path":"phd_tests::migrate::from_base::serial_history"}
1582026-11-06T00:30:36.250Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.218677226Z","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-11-06T00:30:36.252Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.21880725Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
1602026-11-06T00:30:36.252Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.218872699Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1612026-11-06T00:30:36.252Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:36.218944009Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/12b00ba88d088e0c61b2d4d26f765fc83f6a76b8/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1622026-11-06T00:30:55.866Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:55.842552283Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
1632026-11-06T00:30:55.866Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:30:55.842645309Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::serial_history"}
1642026-11-06T00:31:22.709Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:20.891746965Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
1652026-11-06T00:31:22.744Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:20.892287588Z","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-11-06T00:31:22.744Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:20.982892019Z","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-11-06T00:31:22.744Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:20.996622742Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1682026-11-06T00:31:22.745Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.009124331Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1692026-11-06T00:31:22.745Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.015200699Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":44792,"path":"phd_tests::migrate::from_base::serial_history"}
1702026-11-06T00:31:22.772Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.821050457Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-11-06T00:31:22.776Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.825208635Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 1a0b1491-69a9-49c7-9609-6936f5a2cc57, name: \"phd-vm-1a0b1491-69a9-49c7-9609-6936f5a2cc57\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 5eb9dff8-3da1-48e1-bc91-0fae856bffba, project_id: 9e6bc08c-4880-479f-aabe-5a8480190480, sled_id: db3a536f-1f6c-4a5b-9a81-9ea62c4fd2f5, sled_serial: \"db3a536f-1f6c-4a5b-9a81-9ea62c4fd2f5\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1722026-11-06T00:31:22.776Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.825340164Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1732026-11-06T00:31:22.776Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.825394327Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1742026-11-06T00:31:22.776Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.827110965Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1752026-11-06T00:31:22.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.828330383Z","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-11-06T00:31:22.776Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.828410585Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","timeout_duration":"300s","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","path":"phd_tests::migrate::from_base::serial_history"}
1772026-11-06T00:31:22.777Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.828467172Z","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-11-06T00:31:22.777Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.828518088Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1792026-11-06T00:31:22.777Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:21.829088187Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1802026-11-06T00:31:26.294Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.269710821Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4441,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1812026-11-06T00:31:26.294Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.269813435Z","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-11-06T00:31:26.318Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.272822361Z","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-11-06T00:31:26.319Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.272882765Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1842026-11-06T00:31:26.319Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.272927119Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1852026-11-06T00:31:26.344Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.299136117Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":26,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1862026-11-06T00:31:26.344Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.29931755Z","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-11-06T00:31:26.344Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.299785526Z","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-11-06T00:31:26.344Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.299899251Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1892026-11-06T00:31:26.344Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.299992618Z","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::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1902026-11-06T00:31:26.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.332575228Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1912026-11-06T00:31:26.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.332702609Z","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-11-06T00:31:26.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.332783452Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4504,"path":"phd_tests::migrate::from_base::serial_history"}
1932026-11-06T00:31:26.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.337766762Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1942026-11-06T00:31:26.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.337826094Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1952026-11-06T00:31:26.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.343402937Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":5,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1962026-11-06T00:31:26.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.343650726Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1972026-11-06T00:31:26.370Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.343756907Z","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::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1982026-11-06T00:31:26.401Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.376690572Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
1992026-11-06T00:31:26.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.376966184Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2002026-11-06T00:31:26.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.377078256Z","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::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2012026-11-06T00:31:26.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.387618343Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2022026-11-06T00:31:26.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.387870269Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2032026-11-06T00:31:26.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.387980207Z","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::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2042026-11-06T00:31:26.453Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.420940773Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2052026-11-06T00:31:26.477Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.432742886Z","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-11-06T00:31:26.477Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.432875988Z","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-11-06T00:31:26.477Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.432928638Z","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_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2082026-11-06T00:31:26.477Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.434656868Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","sha256":"None","path":"phd_tests::migrate::from_base::serial_history"}
2092026-11-06T00:31:26.478Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.434722813Z","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-11-06T00:31:26.478Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.434779029Z","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::serial_history"}
2112026-11-06T00:31:26.478Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.43484782Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2122026-11-06T00:31:26.503Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 929","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.479281007Z","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-11-06T00:31:26.528Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.490040057Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":57,"path":"phd_tests::migrate::from_base::serial_history"}
2142026-11-06T00:31:26.528Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.490142651Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2152026-11-06T00:31:26.528Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.490722129Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"50813a42-ffbb-4be5-b26e-59796caf9d0f","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2162026-11-06T00:31:26.528Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.490795197Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e","source":"migration_serial_history_base","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e","vm":"migration_serial_history_base_lifecycle_0"}
2172026-11-06T00:31:26.529Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:26.491373842Z","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)","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e","source":"migration_serial_history_base","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e","vm":"migration_serial_history_base_lifecycle_0"}
2182026-11-06T00:31:27.128Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:27.104203092Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e, name: \"phd-vm-bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 5eb9dff8-3da1-48e1-bc91-0fae856bffba, project_id: 9e6bc08c-4880-479f-aabe-5a8480190480, sled_id: 44ec7072-19a2-4e28-ad53-3ab79ee6c05b, sled_serial: \"44ec7072-19a2-4e28-ad53-3ab79ee6c05b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e","source":"migration_serial_history_base","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e","vm":"migration_serial_history_base_lifecycle_0"}
2192026-11-06T00:31:27.153Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:27.104434189Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","migration_id":"50813a42-ffbb-4be5-b26e-59796caf9d0f","source":"migration_serial_history_base","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2202026-11-06T00:31:29.486Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:29.461795813Z","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-11-06T00:31:31.386Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.362783996Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2222026-11-06T00:31:31.387Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.362845132Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","migration_id":"50813a42-ffbb-4be5-b26e-59796caf9d0f","source":"migration_serial_history_base","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","elapsed_milliseconds":4257,"target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2232026-11-06T00:31:31.412Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.365614522Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2242026-11-06T00:31:31.412Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.370910181Z","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":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2252026-11-06T00:31:31.412Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.372890019Z","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":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2262026-11-06T00:31:31.414Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.373073253Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2272026-11-06T00:31:31.414Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.373185384Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9551}
2282026-11-06T00:31:31.414Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.374311135Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2292026-11-06T00:31:31.414Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.374438196Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2302026-11-06T00:31:31.414Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.375109215Z","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":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2312026-11-06T00:31:31.478Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.454890524Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":85,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2322026-11-06T00:31:31.503Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.45664383Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10459,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base","vm_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57"}
2332026-11-06T00:31:31.844Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.820287471Z","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":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2342026-11-06T00:31:31.913Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.889236914Z","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":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2352026-11-06T00:31:31.913Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.889305324Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-b0be9164-c4e0-44a0-bfbe-06c9c88caa97\"]","verb":"destroy","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2362026-11-06T00:31:31.938Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.912281861Z","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":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2372026-11-06T00:31:31.938Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.912363701Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-e2f0a935-5e44-40a9-a541-88e52bace388\"]","verb":"destroy","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2382026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.926751021Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":553,"path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0","vm_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2392026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.926901135Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","vm":"migration_serial_history_base_lifecycle_0","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":5435,"source":"migration_serial_history_base","target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e","vm_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2402026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.926946221Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":552}
2412026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.927016363Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2422026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.926996325Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":5436,"source":"migration_serial_history_base","source_id":"1a0b1491-69a9-49c7-9609-6936f5a2cc57","target_id":"bbe0d416-5b59-4a5c-8510-1e5cd3d03c4e"}
2432026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.927061208Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2442026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.927058213Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":90799,"path":"phd_tests::migrate::from_base::serial_history"}
2452026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.927108207Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2462026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.927264623Z","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-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.927368019Z","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-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.927439885Z","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-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.927507122Z","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-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.927581343Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2512026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.93735717Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.28G 25.3T 1.28G /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2522026-11-06T00:31:31.964Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.937455315Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-9a301cab-7771-43d8-aeb3-f7d6a055f93f\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-11-06T00:31:32.117Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.952109099Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-9a301cab-7771-43d8-aeb3-f7d6a055f93f\", \"phd-artifacts/phd-clone-549e6628-6613-4540-bcbd-735ecf5e6e7b\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-11-06T00:31:32.144Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.966910615Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-549e6628-6613-4540-bcbd-735ecf5e6e7b\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-11-06T00:31:32.144Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.975299517Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-549e6628-6613-4540-bcbd-735ecf5e6e7b 0B 25.3T 1.28G /phd-artifacts/phd-clone-549e6628-6613-4540-bcbd-735ecf5e6e7b\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-11-06T00:31:32.144Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.976037111Z","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-11-06T00:31:32.144Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.976104479Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2582026-11-06T00:31:32.144Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.976176254Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2592026-11-06T00:31:32.144Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.976241899Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server\"","server_addr":"127.0.0.1:9000","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2602026-11-06T00:31:32.145Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:31.976318524Z","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-11-06T00:31:32.145Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.0208298Z","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-11-06T00:31:32.145Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.032386518Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":56,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2632026-11-06T00:31:32.145Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.032490318Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2642026-11-06T00:31:32.145Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.033215373Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2652026-11-06T00:31:32.734Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.710459998Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2662026-11-06T00:31:32.781Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.711638181Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: ef2e1556-3f2b-449a-99ed-836641d0ce4f, name: \"phd-vm-ef2e1556-3f2b-449a-99ed-836641d0ce4f\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 8d01ed6b-bc63-4c4f-aced-278c70dc17f5, project_id: f2fe3f82-cd05-4959-9a64-ef02b90237ac, sled_id: b785b434-306c-427e-8f08-2d3a5fdc913d, sled_serial: \"b785b434-306c-427e-8f08-2d3a5fdc913d\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2672026-11-06T00:31:32.781Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.711851174Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2682026-11-06T00:31:32.782Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.711950412Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2692026-11-06T00:31:32.782Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.712944914Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
2702026-11-06T00:31:32.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.713028382Z","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-11-06T00:31:32.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.713089678Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-11-06T00:31:32.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.713140474Z","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-11-06T00:31:32.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.713186431Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2742026-11-06T00:31:32.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:32.713243469Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2752026-11-06T00:31:37.180Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.15717047Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4443,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
2762026-11-06T00:31:37.180Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.157274757Z","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-11-06T00:31:37.227Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.157467892Z","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-11-06T00:31:37.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.157526082Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2792026-11-06T00:31:37.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.157566672Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2802026-11-06T00:31:37.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.175817881Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
2812026-11-06T00:31:37.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.175946364Z","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-11-06T00:31:37.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.17636165Z","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-11-06T00:31:37.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.17641449Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2842026-11-06T00:31:37.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.176456489Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2852026-11-06T00:31:37.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.20830648Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
2862026-11-06T00:31:37.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.208455512Z","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-11-06T00:31:37.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.208520966Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4494,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2882026-11-06T00:31:37.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.208728513Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2892026-11-06T00:31:37.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.208807967Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2902026-11-06T00:31:37.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.219349643Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
2912026-11-06T00:31:37.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.219535024Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2922026-11-06T00:31:37.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.219615587Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2932026-11-06T00:31:37.281Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.252734232Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
2942026-11-06T00:31:37.281Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.253753715Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2952026-11-06T00:31:37.281Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.253810843Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2962026-11-06T00:31:37.305Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.264283609Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
2972026-11-06T00:31:37.306Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.264532911Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2982026-11-06T00:31:37.306Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.264640936Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2992026-11-06T00:31:37.331Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.297713147Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3002026-11-06T00:31:37.331Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.297974432Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3012026-11-06T00:31:37.331Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.298080793Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3022026-11-06T00:31:37.356Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.309617647Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3032026-11-06T00:31:37.356Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.309853537Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3042026-11-06T00:31:37.356Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.309953458Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3052026-11-06T00:31:37.382Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.341940931Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3062026-11-06T00:31:37.382Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.342179582Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3072026-11-06T00:31:37.382Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.342280178Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3082026-11-06T00:31:37.382Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.352848526Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3092026-11-06T00:31:37.382Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.353097317Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3102026-11-06T00:31:37.382Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.35320506Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3112026-11-06T00:31:37.409Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.386173289Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3122026-11-06T00:31:37.435Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.386487796Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3132026-11-06T00:31:37.435Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.386672791Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3142026-11-06T00:31:37.435Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.397187666Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3152026-11-06T00:31:37.436Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.397437168Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3162026-11-06T00:31:37.436Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.397545604Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3172026-11-06T00:31:37.461Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.430605071Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3182026-11-06T00:31:37.461Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.431711355Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3192026-11-06T00:31:37.462Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.43181994Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3202026-11-06T00:31:37.488Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.441406048Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3212026-11-06T00:31:37.488Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.441664397Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3222026-11-06T00:31:37.488Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.441773053Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3232026-11-06T00:31:37.513Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.474025225Z","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::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3242026-11-06T00:31:37.513Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.474222247Z","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-11-06T00:31:37.513Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.474365368Z","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-11-06T00:31:37.513Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.474458534Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3272026-11-06T00:31:37.513Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.474579974Z","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-11-06T00:31:37.513Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.474674686Z","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-11-06T00:31:37.513Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.47479806Z","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-11-06T00:31:37.544Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 939","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.520941119Z","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-11-06T00:31:37.570Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.531214908Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":56,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3322026-11-06T00:31:37.571Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.531299378Z","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","source":"migration_from_base","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","target":"migration_from_base_lifecycle_0"}
3332026-11-06T00:31:37.571Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.531364321Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"94f1373e-3853-43d4-b6ad-ecd97b1720ba","timeout_duration":"45s","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","target":"migration_from_base_lifecycle_0"}
3342026-11-06T00:31:37.571Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.531431088Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","target":"migration_from_base_lifecycle_0"}
3352026-11-06T00:31:37.571Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:37.531949437Z","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_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","target":"migration_from_base_lifecycle_0"}
3362026-11-06T00:31:38.150Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:38.126842688Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 16b9023a-3669-4f46-817e-0bb63db6334a, name: \"phd-vm-16b9023a-3669-4f46-817e-0bb63db6334a\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 8d01ed6b-bc63-4c4f-aced-278c70dc17f5, project_id: f2fe3f82-cd05-4959-9a64-ef02b90237ac, sled_id: 82b408cc-9781-48b2-85b0-e5b3527f38d0, sled_serial: \"82b408cc-9781-48b2-85b0-e5b3527f38d0\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","target":"migration_from_base_lifecycle_0"}
3372026-11-06T00:31:38.175Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:38.127097486Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"94f1373e-3853-43d4-b6ad-ecd97b1720ba","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","target":"migration_from_base_lifecycle_0"}
3382026-11-06T00:31:40.526Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:40.502862238Z","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-11-06T00:31:41.032Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.009429902Z","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","source":"migration_from_base","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","target":"migration_from_base_lifecycle_0"}
3402026-11-06T00:31:41.032Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.009488241Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"94f1373e-3853-43d4-b6ad-ecd97b1720ba","elapsed_milliseconds":2881,"path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","target":"migration_from_base_lifecycle_0"}
3412026-11-06T00:31:41.057Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.011467837Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3422026-11-06T00:31:41.058Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.011683535Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3432026-11-06T00:31:41.058Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.011743439Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo 3 > /proc/sys/vm/drop_caches","timeout_duration":"Explicit(15s)","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3442026-11-06T00:31:41.058Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.013273574Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3452026-11-06T00:31:41.119Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.0968329Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":85,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3462026-11-06T00:31:41.144Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.097004986Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9062,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f"}
3472026-11-06T00:31:41.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.097148958Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":85,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3482026-11-06T00:31:41.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.097404903Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3492026-11-06T00:31:41.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.09751455Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3502026-11-06T00:31:41.169Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.133564036Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":36,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3512026-11-06T00:31:41.169Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.133890975Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3522026-11-06T00:31:41.169Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.134015781Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3532026-11-06T00:31:41.169Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.144625243Z","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::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3542026-11-06T00:31:41.169Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.144953344Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3552026-11-06T00:31:41.169Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.145072199Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3562026-11-06T00:31:41.252Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.176879419Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3572026-11-06T00:31:41.252Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.177161343Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3582026-11-06T00:31:41.252Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.177281911Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3592026-11-06T00:31:41.252Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.188699402Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3602026-11-06T00:31:41.252Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.188958653Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3612026-11-06T00:31:41.252Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.189066587Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3622026-11-06T00:31:41.277Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.221922211Z","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::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3632026-11-06T00:31:41.277Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.222207521Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3642026-11-06T00:31:41.277Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.222317469Z","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)","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3652026-11-06T00:31:41.277Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.232876606Z","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::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3662026-11-06T00:31:41.277Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.233130898Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3672026-11-06T00:31:41.277Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.233239974Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3682026-11-06T00:31:41.301Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.2666038Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3692026-11-06T00:31:41.301Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.266846048Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3702026-11-06T00:31:41.302Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.266909728Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls /media/nvme0n1/boot","timeout_duration":"Explicit(15s)","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3712026-11-06T00:31:41.302Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.277217771Z","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::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3722026-11-06T00:31:41.302Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.277479276Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3732026-11-06T00:31:41.302Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.277592991Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3742026-11-06T00:31:41.344Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.320888577Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":43,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3752026-11-06T00:31:41.368Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.321127107Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3762026-11-06T00:31:41.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.321306938Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3772026-11-06T00:31:41.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.332708652Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3782026-11-06T00:31:41.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.33295609Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3792026-11-06T00:31:41.369Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.333062962Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3802026-11-06T00:31:41.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.365784561Z","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::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3812026-11-06T00:31:41.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.365984188Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3822026-11-06T00:31:41.393Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.366049272Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"! dmesg | grep -q 'reset controller'","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3832026-11-06T00:31:41.419Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.377569772Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3842026-11-06T00:31:41.419Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.377807427Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3852026-11-06T00:31:41.419Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.377896311Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3862026-11-06T00:31:41.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.410614971Z","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::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3872026-11-06T00:31:41.444Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.410859574Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3882026-11-06T00:31:41.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.410969351Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3892026-11-06T00:31:41.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.421234402Z","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::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3902026-11-06T00:31:41.470Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.421471926Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3912026-11-06T00:31:41.470Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.421571987Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3922026-11-06T00:31:41.495Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.453884897Z","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::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
3932026-11-06T00:31:41.495Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.454046509Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3942026-11-06T00:31:41.495Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.45429843Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3952026-11-06T00:31:41.496Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.454414139Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8742}
3962026-11-06T00:31:41.496Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.454448855Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3972026-11-06T00:31:41.496Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.454570585Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3982026-11-06T00:31:41.496Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:41.456106432Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3992026-11-06T00:31:42.209Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.125057835Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4002026-11-06T00:31:42.234Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.204035667Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4012026-11-06T00:31:42.234Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.20413773Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-549e6628-6613-4540-bcbd-735ecf5e6e7b\"]","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4022026-11-06T00:31:42.259Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.227567519Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4032026-11-06T00:31:42.261Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.227667358Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-9a301cab-7771-43d8-aeb3-f7d6a055f93f\"]","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4042026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244151147Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":789,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a"}
4052026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244347468Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":789}
4062026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244356846Z","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","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","vm_id":"16b9023a-3669-4f46-817e-0bb63db6334a","elapsed_milliseconds":4712,"source":"migration_from_base","vm":"migration_from_base_lifecycle_0","target":"migration_from_base_lifecycle_0"}
4072026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244419084Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
4082026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244463708Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
4092026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244443119Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4712,"path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","source_id":"ef2e1556-3f2b-449a-99ed-836641d0ce4f","target_id":"16b9023a-3669-4f46-817e-0bb63db6334a","target":"migration_from_base_lifecycle_0"}
4102026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244507952Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4112026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244503363Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":10315,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4122026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244654389Z","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-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244764658Z","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-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244831975Z","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-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244893321Z","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-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.244964736Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4172026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.254152178Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.28G 25.3T 1.28G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-11-06T00:31:42.309Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.254285831Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-c317f04f-0753-4811-ad89-20231d550acb\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4192026-11-06T00:31:42.359Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.268181653Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-c317f04f-0753-4811-ad89-20231d550acb\", \"phd-artifacts/phd-clone-6893ff6d-571d-44dc-9252-8655a1779145\"]","verb":"clone","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4202026-11-06T00:31:42.359Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.282234411Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-6893ff6d-571d-44dc-9252-8655a1779145\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4212026-11-06T00:31:42.359Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.289711668Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-6893ff6d-571d-44dc-9252-8655a1779145 0B 25.3T 1.28G /phd-artifacts/phd-clone-6893ff6d-571d-44dc-9252-8655a1779145\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4222026-11-06T00:31:42.359Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.290212809Z","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-11-06T00:31:42.359Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.290274361Z","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","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4242026-11-06T00:31:42.359Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.290398657Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4252026-11-06T00:31:42.359Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.290459822Z","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/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4262026-11-06T00:31:42.360Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.290550043Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4272026-11-06T00:31:42.386Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 948","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.336010596Z","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-11-06T00:31:42.386Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.348040677Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":57,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4292026-11-06T00:31:42.386Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.348151406Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4302026-11-06T00:31:42.386Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.348862582Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4312026-11-06T00:31:42.897Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.873998538Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
4322026-11-06T00:31:42.944Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.875038766Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6, name: \"phd-vm-ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 75bddeb6-e83d-4922-afa2-49681fad6504, project_id: 09207d4f-91a7-4ec7-99eb-f466a56e1f4f, sled_id: 341de1b8-31c7-4f53-91d2-8e91422548ed, sled_serial: \"341de1b8-31c7-4f53-91d2-8e91422548ed\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4332026-11-06T00:31:42.944Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.875199791Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4342026-11-06T00:31:42.944Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.875263271Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4352026-11-06T00:31:42.945Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.876323007Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":1,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4362026-11-06T00:31:42.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.876411234Z","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-11-06T00:31:42.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.876474012Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","timeout_duration":"300s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4382026-11-06T00:31:42.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.876524889Z","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-11-06T00:31:42.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.876572449Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4402026-11-06T00:31:42.945Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:42.876625259Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4412026-11-06T00:31:47.348Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.324956449Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":4447,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4422026-11-06T00:31:47.348Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.325062991Z","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-11-06T00:31:47.348Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.325260545Z","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-11-06T00:31:47.372Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.325320929Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4452026-11-06T00:31:47.372Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.325366906Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4462026-11-06T00:31:47.374Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.343750578Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4472026-11-06T00:31:47.374Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.343900271Z","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-11-06T00:31:47.374Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.344341546Z","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-11-06T00:31:47.374Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.344434232Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-11-06T00:31:47.374Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.344481571Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-11-06T00:31:47.399Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.377367302Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4522026-11-06T00:31:47.399Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.377481011Z","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-11-06T00:31:47.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.377555665Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4500,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-11-06T00:31:47.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.377785872Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4552026-11-06T00:31:47.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.377908391Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4562026-11-06T00:31:47.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.38862407Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4572026-11-06T00:31:47.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.388870666Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4582026-11-06T00:31:47.426Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.38897828Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4592026-11-06T00:31:47.451Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.410887041Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":21,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4602026-11-06T00:31:47.451Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.411155298Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4612026-11-06T00:31:47.451Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.411265717Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4622026-11-06T00:31:47.451Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.421728914Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4632026-11-06T00:31:47.451Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.421959328Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4642026-11-06T00:31:47.451Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.422060084Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4652026-11-06T00:31:47.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.455208137Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4662026-11-06T00:31:47.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.455465754Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4672026-11-06T00:31:47.478Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.455551246Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4682026-11-06T00:31:47.505Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.465980315Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4692026-11-06T00:31:47.505Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.466289893Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4702026-11-06T00:31:47.505Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.466397838Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4712026-11-06T00:31:47.529Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.499592202Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4722026-11-06T00:31:47.529Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.499919822Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4732026-11-06T00:31:47.529Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.500042144Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4742026-11-06T00:31:47.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.510518174Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4752026-11-06T00:31:47.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.5107583Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762026-11-06T00:31:47.554Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.510859836Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772026-11-06T00:31:47.579Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.543010801Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-11-06T00:31:47.579Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.543293326Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-11-06T00:31:47.579Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.543387965Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-11-06T00:31:47.579Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.554773165Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-11-06T00:31:47.579Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.554889334Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4822026-11-06T00:31:47.580Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.554939858Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4832026-11-06T00:31:47.604Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.577742916Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4842026-11-06T00:31:47.604Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.578010412Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4852026-11-06T00:31:47.604Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.57812038Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4862026-11-06T00:31:47.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.588685489Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4872026-11-06T00:31:47.628Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.589028688Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4882026-11-06T00:31:47.629Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.589142083Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4892026-11-06T00:31:47.654Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.610771777Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":21,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4902026-11-06T00:31:47.654Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.610962218Z","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-11-06T00:31:47.655Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.61110595Z","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-11-06T00:31:47.655Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.611197172Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4932026-11-06T00:31:47.655Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.611311125Z","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-11-06T00:31:47.655Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.611403493Z","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-11-06T00:31:47.655Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.611527018Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4962026-11-06T00:31:47.680Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 949","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.655248742Z","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-11-06T00:31:47.704Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.665374866Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":54,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4982026-11-06T00:31:47.704Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.665470528Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4992026-11-06T00:31:47.704Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.665549146Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d9847f27-27ae-4947-8d47-0f3f6eecf30a","timeout_duration":"45s","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5002026-11-06T00:31:47.704Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.665621223Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
5012026-11-06T00:31:47.704Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:47.666213303Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
5022026-11-06T00:31:48.494Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:48.47192796Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991, name: \"phd-vm-9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 75bddeb6-e83d-4922-afa2-49681fad6504, project_id: 09207d4f-91a7-4ec7-99eb-f466a56e1f4f, sled_id: b696d561-0a86-41aa-aa6c-055ed631e058, sled_serial: \"b696d561-0a86-41aa-aa6c-055ed631e058\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
5032026-11-06T00:31:48.519Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:48.472142636Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d9847f27-27ae-4947-8d47-0f3f6eecf30a","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5042026-11-06T00:31:50.830Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:50.808206279Z","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-11-06T00:31:52.608Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.586148467Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-11-06T00:31:52.608Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.586211146Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d9847f27-27ae-4947-8d47-0f3f6eecf30a","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4113}
5072026-11-06T00:31:52.633Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.588293707Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-11-06T00:31:52.633Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.58851229Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-11-06T00:31:52.633Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.588571743Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5102026-11-06T00:31:52.633Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.590024472Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base_and_back","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5112026-11-06T00:31:52.696Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.67454633Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":86,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5122026-11-06T00:31:52.744Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.67474835Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","vm":"migration_from_base_and_back","elapsed_milliseconds":10324,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5132026-11-06T00:31:52.744Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.674836773Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":86,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5142026-11-06T00:31:52.744Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.675120544Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5152026-11-06T00:31:52.744Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.675198471Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5162026-11-06T00:31:52.744Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.699261545Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":24,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5172026-11-06T00:31:52.745Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.69937005Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__BASE_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5182026-11-06T00:31:52.745Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.699455392Z","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-11-06T00:31:52.745Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.69951299Z","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-11-06T00:31:52.745Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.6995764Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5212026-11-06T00:31:52.745Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.699629845Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/71b15fc0469de84be478d8f280bcc0a85e30ef6c760d34a6bbf9286b61b56fc5/propolis-server\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5222026-11-06T00:31:52.745Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.699698234Z","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-11-06T00:31:52.770Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 951","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.742034698Z","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-11-06T00:31:52.795Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.752800446Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":53,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5252026-11-06T00:31:52.795Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.752898822Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5262026-11-06T00:31:52.795Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.752973183Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"d1ff92e3-cf1e-4198-9791-39ac62dae536","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5272026-11-06T00:31:52.795Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.753043396Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5282026-11-06T00:31:52.795Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:52.753602243Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5292026-11-06T00:31:53.243Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:53.219513225Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: d9c7a0e1-9851-4360-aa1a-db6981298176, name: \"phd-vm-d9c7a0e1-9851-4360-aa1a-db6981298176\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 75bddeb6-e83d-4922-afa2-49681fad6504, project_id: 09207d4f-91a7-4ec7-99eb-f466a56e1f4f, sled_id: af551c41-6f18-4752-996e-d4c59e7bb62f, sled_serial: \"af551c41-6f18-4752-996e-d4c59e7bb62f\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5302026-11-06T00:31:53.244Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:53.219693836Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d1ff92e3-cf1e-4198-9791-39ac62dae536","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5312026-11-06T00:31:55.605Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:55.583495081Z","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-11-06T00:31:57.619Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.598234293Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5332026-11-06T00:31:57.620Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.598358538Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d1ff92e3-cf1e-4198-9791-39ac62dae536","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4377}
5342026-11-06T00:31:57.645Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.600551428Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5352026-11-06T00:31:57.645Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.60075843Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5362026-11-06T00:31:57.645Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.600817331Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5372026-11-06T00:31:57.645Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.602229123Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5382026-11-06T00:31:57.705Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.683967703Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":83,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5392026-11-06T00:31:57.730Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.684153885Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":10016,"source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5402026-11-06T00:31:57.730Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.68425693Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"ed67bf93-b2f4-41e3-bc11-53d9f3d7fce6","target_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10017}
5412026-11-06T00:31:57.730Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.68430952Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":83,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5422026-11-06T00:31:57.730Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.684620859Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5432026-11-06T00:31:57.730Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.684702584Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5442026-11-06T00:31:57.754Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.711375113Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":26,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5452026-11-06T00:31:57.754Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.711538783Z","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"}
5462026-11-06T00:31:57.754Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.711620509Z","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-11-06T00:31:57.754Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.711666946Z","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_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5482026-11-06T00:31:57.754Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.71179401Z","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-11-06T00:31:57.754Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.711858963Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9006","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5502026-11-06T00:31:57.754Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.711928063Z","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_2.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5512026-11-06T00:31:57.779Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 953","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.756052598Z","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-11-06T00:31:57.803Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.766898219Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":55,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5532026-11-06T00:31:57.803Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.766995573Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5542026-11-06T00:31:57.803Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.767071116Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"43b73e11-34dc-4653-a4ec-e8f87d867697","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5552026-11-06T00:31:57.803Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.767136991Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5562026-11-06T00:31:57.803Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:57.767721096Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5572026-11-06T00:31:58.473Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:58.452061702Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 9d34b643-c003-488b-bc73-9f0a93427af1, name: \"phd-vm-9d34b643-c003-488b-bc73-9f0a93427af1\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 75bddeb6-e83d-4922-afa2-49681fad6504, project_id: 09207d4f-91a7-4ec7-99eb-f466a56e1f4f, sled_id: 45301fe4-9bab-4ee5-aa94-82b9f565e3f8, sled_serial: \"45301fe4-9bab-4ee5-aa94-82b9f565e3f8\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5582026-11-06T00:31:58.473Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:31:58.452284565Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"43b73e11-34dc-4653-a4ec-e8f87d867697","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5592026-11-06T00:32:00.778Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:00.757455186Z","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-11-06T00:32:00.944Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:00.923019753Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5612026-11-06T00:32:00.944Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:00.923078092Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"43b73e11-34dc-4653-a4ec-e8f87d867697","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":2470}
5622026-11-06T00:32:00.969Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:00.92530481Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5632026-11-06T00:32:00.969Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:00.925575282Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5642026-11-06T00:32:00.969Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:00.92564299Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5652026-11-06T00:32:00.969Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:00.927177994Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5662026-11-06T00:32:01.029Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.008018846Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":82,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5672026-11-06T00:32:01.029Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.008142931Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":82,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5682026-11-06T00:32:01.054Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.008313834Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5692026-11-06T00:32:01.054Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.008270442Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":8253,"source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5702026-11-06T00:32:01.054Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.008381422Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5712026-11-06T00:32:01.054Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.008402372Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"9ac2ccb3-80cd-4d3c-b0af-0f0a80c2a991","target_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":8254}
5722026-11-06T00:32:01.082Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.037535472Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":29,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5732026-11-06T00:32:01.082Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.03761937Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5742026-11-06T00:32:01.082Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.037769705Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5752026-11-06T00:32:01.082Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.037887468Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":18160}
5762026-11-06T00:32:01.082Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.038034817Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5772026-11-06T00:32:01.082Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.03820041Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5782026-11-06T00:32:01.082Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.039318205Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5792026-11-06T00:32:01.780Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.759614858Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5802026-11-06T00:32:01.861Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.840012784Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5812026-11-06T00:32:01.861Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.840119376Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-6893ff6d-571d-44dc-9252-8655a1779145\"]","verb":"destroy","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5822026-11-06T00:32:01.885Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.862873626Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5832026-11-06T00:32:01.885Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.862941555Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-c317f04f-0753-4811-ad89-20231d550acb\"]","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5842026-11-06T00:32:01.910Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.878336563Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":840,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5852026-11-06T00:32:01.910Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.878452262Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9d34b643-c003-488b-bc73-9f0a93427af1","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":4110,"source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5862026-11-06T00:32:01.910Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.878521694Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"d9c7a0e1-9851-4360-aa1a-db6981298176","target_id":"9d34b643-c003-488b-bc73-9f0a93427af1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4110}
5872026-11-06T00:32:01.910Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.87852485Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":840}
5882026-11-06T00:32:01.910Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.878576467Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":19630,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5892026-11-06T00:32:01.910Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.878655056Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5902026-11-06T00:32:01.912Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.87872558Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5912026-11-06T00:32:01.912Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 120.75s
5922026-11-06T00:32:01.912Z
5932026-11-06T00:32:01.912Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":923,"time":"2026-11-06T00:32:01.878855956Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5942026-11-06T00:32:02.023Z
5952026-11-06T00:32:02.077Zreal 2:04.484179254
5962026-11-06T00:32:02.077Zuser 51.310714479
5972026-11-06T00:32:02.077Zsys 19.321625494
5982026-11-06T00:32:02.077Ztrap 0.007077613
5992026-11-06T00:32:02.077Ztflt 0.007801785
6002026-11-06T00:32:02.077Zdflt 0.002509261
6012026-11-06T00:32:02.077Zkflt 0.000000000
6022026-11-06T00:32:02.077Zlock 4:44:18.382923303
6032026-11-06T00:32:02.077Zslp 4:43.930327855
6042026-11-06T00:32:02.078Zlat 1.896647651
6052026-11-06T00:32:02.078Zstop 38.044110767
6062026-11-06T00:32:02.078Z+ failcount=0
6072026-11-06T00:32:02.078Z+ set -e
6082026-11-06T00:32:02.078Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
6092026-11-06T00:32:02.078ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
6102026-11-06T00:32:02.078Za ./ 0K
6112026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::serial_history/ 0K
6122026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 159K
6132026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
6142026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
6152026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 165K
6162026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
6172026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
6182026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 157K
6192026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
6202026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
6212026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 164K
6222026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
6232026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
6242026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 158K
6252026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
6262026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
6272026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 269K
6282026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
6292026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 269K
6302026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
6312026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 164K
6322026-11-06T00:32:02.078Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
6332026-11-06T00:32:02.103Z+ exitcode=0
6342026-11-06T00:32:02.103Z+ '[' 0 -eq 0 ']'
6352026-11-06T00:32:02.103Z+ echo
6362026-11-06T00:32:02.103Z
6372026-11-06T00:32:02.103Z+ echo 'ALL TESTS PASSED'
6382026-11-06T00:32:02.103ZALL TESTS PASSED
6392026-11-06T00:32:02.103Z
6402026-11-06T00:32:02.103Z+ echo
6412026-11-06T00:32:02.103Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6422026-11-06T00:32:02.103Z+ read
6432026-11-06T00:32:02.103Z+ exit 0
6442026-11-06T00:32:02.103Zprocess exited: duration 183968 ms, exit code 0
 
6452026-11-06T00:32:02.156Zfound 2 output files
6462026-11-06T00:32:02.183Zuploading: /tmp/phd-runner.log (202740 bytes)
6472026-11-06T00:32:04.005Zuploaded: /tmp/phd-runner.log
6482026-11-06T00:32:04.005Zuploading: /tmp/phd-tmp-files.tar.gz (133814 bytes)
6492026-11-06T00:32:05.552Zuploaded: /tmp/phd-tmp-files.tar.gz