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

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

Buildomat Job: 01M29BCZ1H3V54BJV59E791ZDK

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-09-11T23:15:11.776Zjob dependencies complete; ready to run (waiting for 11 m 23 s)
22026-09-11T23:23:20.972Zjob assigned to worker 01M29C1VECVG2W3B86RXPZ6WQ8 [factory edgar, gimlet/BRM42220010/1537] (queued for 8 m 9 s)
32026-09-11T23:23:21.598Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-09-11T23:23:21.622Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-09-11T23:23:21.622Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-09-11T23:23:21.656Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-09-11T23:23:21.656Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-09-11T23:23:30.498Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-09-11T23:23:30.498Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-09-11T23:23:30.546Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-09-11T23:23:30.570Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-09-11T23:23:42.606Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-09-11T23:23:42.606Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-09-11T23:23:53.167Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-09-11T23:23:53.167Zstarting task 0: "setup"
162026-09-11T23:23:53.194Z++ uname -s
172026-09-11T23:23:53.194Z+ kern=SunOS
182026-09-11T23:23:53.194Z+ build_user=build
192026-09-11T23:23:53.194Z+ build_uid=12345
202026-09-11T23:23:53.194Z+ work_dir=/work
212026-09-11T23:23:53.194Z+ input_dir=/input
222026-09-11T23:23:53.194Z+ [[ 0 == 12345 ]]
232026-09-11T23:23:53.194Z+ case "$kern" in
242026-09-11T23:23:53.194Z+ groupadd -g 12345 build
252026-09-11T23:23:53.194Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-09-11T23:23:55.216Z+ zfs create -o mountpoint=/work rpool/work
272026-09-11T23:23:55.513Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-09-11T23:23:55.537Z+ home_fs=
292026-09-11T23:23:55.537Z+ [[ '' == autofs ]]
302026-09-11T23:23:55.537Z+ mkdir -p /home/build
312026-09-11T23:23:55.537Z+ chown build:build /home/build /work
322026-09-11T23:23:57.527Z+ chmod 0700 /home/build /work
332026-09-11T23:23:57.551Zprocess exited: duration 4364 ms, exit code 0
 
342026-09-11T23:23:57.599Zstarting task 1: "authentication"
352026-09-11T23:23:57.669Zprocess exited: duration 69 ms, exit code 0
 
362026-09-11T23:23:57.718Zstarting task 2: "build"
372026-09-11T23:23:57.744Z+ indir=/input
382026-09-11T23:23:57.744Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-09-11T23:23:57.744Z+ phddir=/work/phd-test
402026-09-11T23:23:57.744Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-09-11T23:23:57.769Z++ pilot local disk list -H -o type,disk
422026-09-11T23:23:57.769Z++ grep -v M.2
432026-09-11T23:23:57.769Z++ cut -f 2
442026-09-11T23:23:57.820Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
452026-09-11T23:24:00.385Z+ artifactdir=/phd-artifacts
462026-09-11T23:24:00.385Z+ banner Inputs
472026-09-11T23:24:00.415Z ###
482026-09-11T23:24:00.415Z # # # ##### # # ##### ####
492026-09-11T23:24:00.415Z # ## # # # # # # #
502026-09-11T23:24:00.415Z # # # # # # # # # ####
512026-09-11T23:24:00.415Z # # # # ##### # # # #
522026-09-11T23:24:00.415Z # # ## # # # # # #
532026-09-11T23:24:00.415Z ### # # # #### # ####
542026-09-11T23:24:00.415Z
552026-09-11T23:24:00.415Z+ find /input -ls
562026-09-11T23:24:00.415Z 34 1 drwxr-xr-x 3 root root 3 Sep 11 23:23 /input
572026-09-11T23:24:00.415Z 2 1 drwxr-xr-x 3 root root 3 Sep 11 23:23 /input/phd-build
582026-09-11T23:24:00.415Z 3 2 drwxr-xr-x 2 root root 8 Sep 11 23:23 /input/phd-build/out
592026-09-11T23:24:00.415Z 256 1 -rw-r--r-- 1 root root 65 Sep 11 23:23 /input/phd-build/out/propolis-server-debug.sha256.txt
602026-09-11T23:24:00.415Z 130 187914 -rw-r--r-- 1 root root 192324357 Sep 11 23:23 /input/phd-build/out/phd-runner.tar.gz
612026-09-11T23:24:00.415Z 512 221273 -rw-r--r-- 1 root root 226519322 Sep 11 23:23 /input/phd-build/out/propolis-tests-debug.tar.gz
622026-09-11T23:24:00.415Z 128 2 -rw-r--r-- 1 root root 2573 Sep 11 23:23 /input/phd-build/out/phd-run-with-args.sh
632026-09-11T23:24:00.415Z 384 261807 -rw-r--r-- 1 root root 268038481 Sep 11 23:23 /input/phd-build/out/propolis-server-debug.tar.gz
642026-09-11T23:24:00.415Z 129 1 -rw-r--r-- 1 root root 65 Sep 11 23:23 /input/phd-build/out/phd-runner.sha256.txt
652026-09-11T23:24:00.415Z+ rm -rf /work/phd-test
662026-09-11T23:24:00.415Z+ mkdir /work/phd-test
672026-09-11T23:24:00.415Z+ for p in $indir/$indir_suffix
682026-09-11T23:24:00.415Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-09-11T23:24:15.756ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-09-11T23:24:15.756Zx phd-runner, 737139024 bytes, 1439725 tape blocks
712026-09-11T23:24:15.756Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-09-11T23:24:15.780Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-09-11T23:24:20.555Z+ for f in $(tar tf "$p")
742026-09-11T23:24:20.555Z+ chmod +x /work/phd-test/phd-runner
752026-09-11T23:24:20.580Z+ for f in $(tar tf "$p")
762026-09-11T23:24:20.580Z+ chmod +x /work/phd-test/artifacts.toml
772026-09-11T23:24:20.580Z+ for p in $indir/$indir_suffix
782026-09-11T23:24:20.580Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-09-11T23:24:39.121ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-09-11T23:24:39.121Zx propolis-server, 1074453960 bytes, 2098543 tape blocks
812026-09-11T23:24:39.146Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-09-11T23:24:46.080Z+ for f in $(tar tf "$p")
832026-09-11T23:24:46.080Z+ chmod +x /work/phd-test/propolis-server
842026-09-11T23:24:46.104Z+ for p in $indir/$indir_suffix
852026-09-11T23:24:46.104Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-09-11T23:25:02.848ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-09-11T23:25:02.848Zx target/debug/deps/propolis-9fe79620acc72933, 907634008 bytes, 1772723 tape blocks
882026-09-11T23:25:02.873Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-09-11T23:25:08.545Z+ for f in $(tar tf "$p")
902026-09-11T23:25:08.545Z+ chmod +x /work/phd-test/target/debug/deps/propolis-9fe79620acc72933
912026-09-11T23:25:08.570Z+ ls /work/phd-test
922026-09-11T23:25:08.570Zartifacts.toml
932026-09-11T23:25:08.570Zphd-runner
942026-09-11T23:25:08.570Zpropolis-server
952026-09-11T23:25:08.570Ztarget
962026-09-11T23:25:08.570Z+ banner Setup
972026-09-11T23:25:08.570Z #####
982026-09-11T23:25:08.570Z# # ###### ##### # # #####
992026-09-11T23:25:08.570Z# # # # # # #
1002026-09-11T23:25:08.570Z ##### ##### # # # # #
1012026-09-11T23:25:08.570Z # # # # # #####
1022026-09-11T23:25:08.571Z# # # # # # #
1032026-09-11T23:25:08.571Z ##### ###### # #### #
1042026-09-11T23:25:08.571Z
1052026-09-11T23:25:08.571Z+ tmpdir=/tmp/propolis-phd
1062026-09-11T23:25:08.571Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-09-11T23:25:08.571Z+ mkdir /tmp/propolis-phd
1082026-09-11T23:25:08.571Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-09-11T23:25:09.033Z+ banner Tests
1102026-09-11T23:25:09.058Z#######
1112026-09-11T23:25:09.058Z # ###### #### ##### ####
1122026-09-11T23:25:09.058Z # # # # #
1132026-09-11T23:25:09.058Z # ##### #### # ####
1142026-09-11T23:25:09.058Z # # # # #
1152026-09-11T23:25:09.058Z # # # # # # #
1162026-09-11T23:25:09.058Z # ###### #### # ####
1172026-09-11T23:25:09.058Z
1182026-09-11T23:25:09.058Z+ runner=/work/phd-test/phd-runner
1192026-09-11T23:25:09.058Z+ artifacts=/work/phd-test/artifacts.toml
1202026-09-11T23:25:09.058Z+ propolis=/work/phd-test/propolis-server
1212026-09-11T23:25:09.058Z+ ls /work/phd-test/phd-runner
1222026-09-11T23:25:09.058Z/work/phd-test/phd-runner
1232026-09-11T23:25:09.058Z+ ls /work/phd-test/artifacts.toml
1242026-09-11T23:25:09.059Z/work/phd-test/artifacts.toml
1252026-09-11T23:25:09.059Z+ ls /work/phd-test/propolis-server
1262026-09-11T23:25:09.059Z/work/phd-test/propolis-server
1272026-09-11T23:25:09.059Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-09-11T23:25:09.059Z+ set +e
1292026-09-11T23:25:09.059Z+ RUST_BACKTRACE=1
1302026-09-11T23:25:09.059Z+ RUST_LOG=info,phd=debug
1312026-09-11T23:25:09.059Z+ 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-09-11T23:25:09.059Z+ tee /tmp/phd-runner.log
1332026-09-11T23:25:09.249Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:09.221796678Z","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-09-11T23:25:09.274Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:09.248751561Z","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: 262, tv_nsec: 995606672 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-09-11T23:25:09.274Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:09.249343113Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-09-11T23:25:09.274Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:09.250363308Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"ad8a31742adc45e925e63443a5b43c8e30604022"}
1372026-09-11T23:25:09.298Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:09.256220285Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/ad8a31742adc45e925e63443a5b43c8e30604022/crucible-nightly.sha256.txt","timeout":"600s"}
1382026-09-11T23:25:10.917Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:10.899447392Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-09-11T23:25:11.525Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.506811424Z","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/0f7d5179bc4b2c40c459c4ec46da4b83b6cab012/propolis-server.sha256.txt","timeout":"600s"}
1402026-09-11T23:25:11.698Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.679784308Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-09-11T23:25:11.724Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.680606197Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-09-11T23:25:11.724Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.682463289Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-09-11T23:25:11.724Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.683060812Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-09-11T23:25:11.724Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.683095648Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-09-11T23:25:11.724Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.683130214Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-09-11T23:25:11.724Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.684257181Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
1472026-09-11T23:25:11.725Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.685602923Z","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-09-11T23:25:11.725Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:11.687498594Z","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-09-11T23:25:12.200Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:12.181730979Z","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-09-11T23:25:12.225Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:12.19443852Z","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-09-11T23:25:18.898Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.878305971Z","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-09-11T23:25:18.898Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.878437283Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::serial_history"}
1532026-09-11T23:25:18.923Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.893959565Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 3.38M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
1542026-09-11T23:25:18.923Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.895293215Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-8353850c-907d-458d-a837-6efdfe77aa8f\"]","path":"phd_tests::migrate::from_base::serial_history"}
1552026-09-11T23:25:18.947Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.917269927Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-8353850c-907d-458d-a837-6efdfe77aa8f\", \"phd-artifacts/phd-clone-aa8eb0d6-945c-4eda-98cc-56964315be60\"]","verb":"clone","path":"phd_tests::migrate::from_base::serial_history"}
1562026-09-11T23:25:18.972Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.932842028Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-aa8eb0d6-945c-4eda-98cc-56964315be60\"]","path":"phd_tests::migrate::from_base::serial_history"}
1572026-09-11T23:25:18.972Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.944068476Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-aa8eb0d6-945c-4eda-98cc-56964315be60 0B 25.3T 49.0M /phd-artifacts/phd-clone-aa8eb0d6-945c-4eda-98cc-56964315be60\n","path":"phd_tests::migrate::from_base::serial_history"}
1582026-09-11T23:25:18.972Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.948134757Z","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-09-11T23:25:18.972Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.94874237Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
1602026-09-11T23:25:18.972Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.948814326Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/903f697d837d6b6f2fbe07ebb851ef9db604f21ea684fb3a5ca2409f41c97c70/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1612026-09-11T23:25:18.972Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:18.948901381Z","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/0f7d5179bc4b2c40c459c4ec46da4b83b6cab012/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1622026-09-11T23:25:36.019Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:36.000930635Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","untar_path":"propolis-server","extracted_path":"/phd-artifacts/903f697d837d6b6f2fbe07ebb851ef9db604f21ea684fb3a5ca2409f41c97c70/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
1632026-09-11T23:25:36.019Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:25:36.001015355Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::serial_history"}
1642026-09-11T23:26:01.121Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.102669324Z","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/903f697d837d6b6f2fbe07ebb851ef9db604f21ea684fb3a5ca2409f41c97c70/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
1652026-09-11T23:26:01.121Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.102792017Z","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-09-11T23:26:01.269Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 917","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.25171006Z","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-09-11T23:26:01.294Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.26766263Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1682026-09-11T23:26:01.318Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.280674737Z","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":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1692026-09-11T23:26:01.318Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.283652572Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":42333,"path":"phd_tests::migrate::from_base::serial_history"}
1702026-09-11T23:26:01.889Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.871276101Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-09-11T23:26:01.913Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.876998112Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 885c0c48-10f8-44aa-9c45-7a8909234499, name: \"phd-vm-885c0c48-10f8-44aa-9c45-7a8909234499\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: a46d5410-3711-4317-9a73-5fa17c2162c8, project_id: 4b205b47-4988-44f7-aa73-bb2eb47b235e, sled_id: e5ac4bc3-5e6e-4a93-8318-525dcf0620f3, sled_serial: \"e5ac4bc3-5e6e-4a93-8318-525dcf0620f3\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1722026-09-11T23:26:01.913Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.877175609Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1732026-09-11T23:26:01.913Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.877241333Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1742026-09-11T23:26:01.914Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.879471944Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":2,"path":"phd_tests::migrate::from_base::serial_history"}
1752026-09-11T23:26:01.914Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.879629552Z","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-09-11T23:26:01.914Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.879709364Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
1772026-09-11T23:26:01.914Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.8797652Z","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-09-11T23:26:01.914Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.879847726Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1792026-09-11T23:26:01.914Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:01.879904474Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1802026-09-11T23:26:06.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.458609913Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":4578,"path":"phd_tests::migrate::from_base::serial_history"}
1812026-09-11T23:26:06.476Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.458715483Z","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-09-11T23:26:06.500Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.461718538Z","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-09-11T23:26:06.500Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.461784774Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1842026-09-11T23:26:06.500Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.461838065Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1852026-09-11T23:26:06.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.486784872Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":24,"path":"phd_tests::migrate::from_base::serial_history"}
1862026-09-11T23:26:06.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.486939555Z","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-09-11T23:26:06.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.487417562Z","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-09-11T23:26:06.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.487526659Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1892026-09-11T23:26:06.525Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.487616259Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1902026-09-11T23:26:06.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.520281211Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history"}
1912026-09-11T23:26:06.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.520404194Z","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-09-11T23:26:06.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.520482552Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4640,"path":"phd_tests::migrate::from_base::serial_history"}
1932026-09-11T23:26:06.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.52121965Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1942026-09-11T23:26:06.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.521685804Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1952026-09-11T23:26:06.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.530634332Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":8,"path":"phd_tests::migrate::from_base::serial_history"}
1962026-09-11T23:26:06.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.530757726Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1972026-09-11T23:26:06.549Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.530810406Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
1982026-09-11T23:26:06.598Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.564035983Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":33,"path":"phd_tests::migrate::from_base::serial_history"}
1992026-09-11T23:26:06.598Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.56442973Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2002026-09-11T23:26:06.598Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.564518308Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2012026-09-11T23:26:06.598Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.574899713Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history"}
2022026-09-11T23:26:06.598Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.575164486Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2032026-09-11T23:26:06.598Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.575268282Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2042026-09-11T23:26:06.626Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.608066016Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history"}
2052026-09-11T23:26:06.650Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.618685285Z","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-09-11T23:26:06.650Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.618817155Z","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-09-11T23:26:06.650Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.618867079Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
2082026-09-11T23:26:06.650Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.619343653Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","sha256":"None","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2092026-09-11T23:26:06.650Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.619408336Z","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-09-11T23:26:06.650Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.619463741Z","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-09-11T23:26:06.650Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.619533714Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2122026-09-11T23:26:06.681Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 918","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.66333365Z","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-09-11T23:26:06.705Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.676619285Z","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-09-11T23:26:06.705Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.676712121Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2152026-09-11T23:26:06.705Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.677186811Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"31b233cc-15ba-48ca-8a23-829db6a6c808","source":"migration_serial_history_base","target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2162026-09-11T23:26:06.705Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.677259008Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source":"migration_serial_history_base","target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2172026-09-11T23:26:06.705Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:06.677798282Z","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":"406bb23d-0f21-48d4-9941-f849c4078c97","source":"migration_serial_history_base","target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2182026-09-11T23:26:07.574Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:07.556248233Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 406bb23d-0f21-48d4-9941-f849c4078c97, name: \"phd-vm-406bb23d-0f21-48d4-9941-f849c4078c97\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: a46d5410-3711-4317-9a73-5fa17c2162c8, project_id: 4b205b47-4988-44f7-aa73-bb2eb47b235e, sled_id: d2984e51-bdd6-4408-9449-5ae1d0c53d68, sled_serial: \"d2984e51-bdd6-4408-9449-5ae1d0c53d68\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source":"migration_serial_history_base","target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2192026-09-11T23:26:07.598Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:07.55758608Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"31b233cc-15ba-48ca-8a23-829db6a6c808","source":"migration_serial_history_base","target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2202026-09-11T23:26:10.069Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:10.050699076Z","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-09-11T23:26:11.264Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.245685576Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2222026-09-11T23:26:11.264Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.245765617Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"31b233cc-15ba-48ca-8a23-829db6a6c808","source":"migration_serial_history_base","target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":3687}
2232026-09-11T23:26:11.288Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.248875906Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2242026-09-11T23:26:11.288Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.252742508Z","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":"885c0c48-10f8-44aa-9c45-7a8909234499","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
2252026-09-11T23:26:11.349Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.330952718Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":79,"path":"phd_tests::migrate::from_base::serial_history"}
2262026-09-11T23:26:11.373Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.331162436Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"885c0c48-10f8-44aa-9c45-7a8909234499","vm":"migration_serial_history_base","elapsed_milliseconds":10062,"path":"phd_tests::migrate::from_base::serial_history"}
2272026-09-11T23:26:11.373Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.334083946Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2282026-09-11T23:26:11.373Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.334710966Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2292026-09-11T23:26:11.373Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.335966507Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9464}
2302026-09-11T23:26:11.373Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.336214487Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2312026-09-11T23:26:11.373Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.33711778Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2322026-09-11T23:26:11.373Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.337215665Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2332026-09-11T23:26:11.994Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:11.975959284Z","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":"406bb23d-0f21-48d4-9941-f849c4078c97","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2342026-09-11T23:26:12.081Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.063212932Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2352026-09-11T23:26:12.081Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.063366413Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-aa8eb0d6-945c-4eda-98cc-56964315be60\"]","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2362026-09-11T23:26:12.111Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.093379101Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2372026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.093443047Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-8353850c-907d-458d-a837-6efdfe77aa8f\"]","verb":"destroy","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
2382026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.111153593Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":776,"path":"phd_tests::migrate::from_base::serial_history"}
2392026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.111464573Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source":"migration_serial_history_base","elapsed_milliseconds":5433,"target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","vm":"migration_serial_history_base_lifecycle_0","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2402026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.11158955Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_serial_history_base","target_id":"406bb23d-0f21-48d4-9941-f849c4078c97","source_id":"885c0c48-10f8-44aa-9c45-7a8909234499","target":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":5434}
2412026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.11164226Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":60423,"path":"phd_tests::migrate::from_base::serial_history"}
2422026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.111907553Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":774}
2432026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.11200707Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2442026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.112048783Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2452026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.112086364Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2462026-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.112249264Z","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-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.11234911Z","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-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.11241485Z","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-09-11T23:26:12.136Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.112476034Z","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-09-11T23:26:12.137Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.112551684Z","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-09-11T23:26:12.161Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.124531862Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2522026-09-11T23:26:12.161Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.124687757Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-854b495b-6550-4ada-8b24-eef5c429f1c4\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-09-11T23:26:12.161Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.141698074Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-854b495b-6550-4ada-8b24-eef5c429f1c4\", \"phd-artifacts/phd-clone-521ab8dd-28a8-4314-b5ea-80cd3939c55f\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-09-11T23:26:12.185Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.157726228Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-521ab8dd-28a8-4314-b5ea-80cd3939c55f\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-09-11T23:26:12.185Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.167710191Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-521ab8dd-28a8-4314-b5ea-80cd3939c55f 0B 25.3T 1.30G /phd-artifacts/phd-clone-521ab8dd-28a8-4314-b5ea-80cd3939c55f\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-09-11T23:26:12.209Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.168288328Z","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-09-11T23:26:12.209Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.168361035Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2582026-09-11T23:26:12.209Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.168445085Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/903f697d837d6b6f2fbe07ebb851ef9db604f21ea684fb3a5ca2409f41c97c70/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2592026-09-11T23:26:12.209Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.168515699Z","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/903f697d837d6b6f2fbe07ebb851ef9db604f21ea684fb3a5ca2409f41c97c70/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2602026-09-11T23:26:12.210Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.168598325Z","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-09-11T23:26:12.234Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 927","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.213680824Z","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-09-11T23:26:12.258Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.227953279Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":59}
2632026-09-11T23:26:12.258Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.228103453Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2642026-09-11T23:26:12.258Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.228847214Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2652026-09-11T23:26:12.641Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.62332499Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2662026-09-11T23:26:12.666Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.624735816Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: dd5052dc-41a8-4ca2-81a0-24503911c781, name: \"phd-vm-dd5052dc-41a8-4ca2-81a0-24503911c781\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: d5aa5b26-9ae0-4287-9316-b490a1f053eb, project_id: 6ca76f17-8f6b-4419-9f04-62517c2bd167, sled_id: 4cd1d0f3-e9d3-4530-9e79-a7f81324502c, sled_serial: \"4cd1d0f3-e9d3-4530-9e79-a7f81324502c\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2672026-09-11T23:26:12.666Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.624903073Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2682026-09-11T23:26:12.666Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.624963728Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2692026-09-11T23:26:12.666Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.626110803Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":1,"vm":"migration_from_base"}
2702026-09-11T23:26:12.666Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.626204802Z","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-09-11T23:26:12.666Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.626268212Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","timeout_duration":"300s","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-09-11T23:26:12.666Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.626318327Z","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-09-11T23:26:12.666Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.626364074Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2742026-09-11T23:26:12.666Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:12.626419008Z","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::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2752026-09-11T23:26:17.178Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.160470703Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4533,"vm":"migration_from_base"}
2762026-09-11T23:26:17.178Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.160567216Z","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-09-11T23:26:17.203Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.160782084Z","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-09-11T23:26:17.203Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.160844252Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2792026-09-11T23:26:17.203Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.160909085Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2802026-09-11T23:26:17.203Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.179202134Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":18,"vm":"migration_from_base"}
2812026-09-11T23:26:17.203Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.179370733Z","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-09-11T23:26:17.203Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.179684598Z","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-09-11T23:26:17.203Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.179758739Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2842026-09-11T23:26:17.203Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.179811008Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2852026-09-11T23:26:17.230Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.212662905Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm":"migration_from_base"}
2862026-09-11T23:26:17.254Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.212817728Z","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-09-11T23:26:17.254Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.212895616Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4586}
2882026-09-11T23:26:17.254Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.21317185Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2892026-09-11T23:26:17.254Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.213282099Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2902026-09-11T23:26:17.254Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.224378803Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":11,"vm":"migration_from_base"}
2912026-09-11T23:26:17.254Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.224627254Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2922026-09-11T23:26:17.254Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.224691626Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2932026-09-11T23:26:17.279Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.256436754Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":31,"vm":"migration_from_base"}
2942026-09-11T23:26:17.279Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.257268932Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2952026-09-11T23:26:17.279Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.257376426Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2962026-09-11T23:26:17.303Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.268058952Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm":"migration_from_base"}
2972026-09-11T23:26:17.303Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.268385992Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2982026-09-11T23:26:17.303Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.268498325Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
2992026-09-11T23:26:17.327Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.300809538Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm":"migration_from_base"}
3002026-09-11T23:26:17.327Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.301072847Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3012026-09-11T23:26:17.327Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.301171953Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3022026-09-11T23:26:17.351Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.311906109Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm":"migration_from_base"}
3032026-09-11T23:26:17.351Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.312225425Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3042026-09-11T23:26:17.351Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.312338429Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3052026-09-11T23:26:17.376Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.345241122Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm":"migration_from_base"}
3062026-09-11T23:26:17.376Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.3455144Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3072026-09-11T23:26:17.376Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.345639918Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3082026-09-11T23:26:17.376Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.355965359Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm":"migration_from_base"}
3092026-09-11T23:26:17.376Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.356157163Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3102026-09-11T23:26:17.376Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.356220633Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3112026-09-11T23:26:17.406Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.388839548Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm":"migration_from_base"}
3122026-09-11T23:26:17.430Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.389129087Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3132026-09-11T23:26:17.430Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.389234677Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3142026-09-11T23:26:17.430Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.400107374Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm":"migration_from_base"}
3152026-09-11T23:26:17.430Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.400356156Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3162026-09-11T23:26:17.430Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.400458981Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3172026-09-11T23:26:17.455Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.433440356Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm":"migration_from_base"}
3182026-09-11T23:26:17.455Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.435055426Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3192026-09-11T23:26:17.455Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.435126972Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3202026-09-11T23:26:17.479Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.443579441Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":8,"vm":"migration_from_base"}
3212026-09-11T23:26:17.479Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.443816721Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3222026-09-11T23:26:17.479Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.443920027Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3232026-09-11T23:26:17.503Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.47675425Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm":"migration_from_base"}
3242026-09-11T23:26:17.504Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.476935133Z","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-09-11T23:26:17.504Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.477074397Z","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-09-11T23:26:17.504Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.477171982Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3272026-09-11T23:26:17.504Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.477290948Z","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-09-11T23:26:17.504Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.477346393Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3292026-09-11T23:26:17.504Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.477418369Z","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::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3302026-09-11T23:26:17.537Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.519502594Z","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-09-11T23:26:17.561Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.532461728Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":55}
3322026-09-11T23:26:17.561Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.532551178Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d"}
3332026-09-11T23:26:17.561Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.53262079Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"363d1ce6-bacf-4cda-8119-8242d495473f","timeout_duration":"45s","source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d"}
3342026-09-11T23:26:17.561Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.532693728Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3352026-09-11T23:26:17.561Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:17.533314355Z","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":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3362026-09-11T23:26:18.302Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:18.284347237Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: c7cfa60a-165e-48a4-a2fb-3314bf6ce50d, name: \"phd-vm-c7cfa60a-165e-48a4-a2fb-3314bf6ce50d\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: d5aa5b26-9ae0-4287-9316-b490a1f053eb, project_id: 6ca76f17-8f6b-4419-9f04-62517c2bd167, sled_id: 8eebdde9-bedd-466f-88b7-7a12d45b11d7, sled_serial: \"8eebdde9-bedd-466f-88b7-7a12d45b11d7\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3372026-09-11T23:26:18.326Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:18.284538861Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","migration_id":"363d1ce6-bacf-4cda-8119-8242d495473f"}
3382026-09-11T23:26:20.791Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.773699178Z","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-09-11T23:26:20.828Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.810431758Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d"}
3402026-09-11T23:26:20.828Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.810520717Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":2525,"source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","migration_id":"363d1ce6-bacf-4cda-8119-8242d495473f"}
3412026-09-11T23:26:20.853Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.813532697Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3422026-09-11T23:26:20.853Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.813853575Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3432026-09-11T23:26:20.853Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.813925562Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3442026-09-11T23:26:20.854Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.815343351Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","vm":"migration_from_base"}
3452026-09-11T23:26:20.909Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.890908525Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":77,"vm":"migration_from_base"}
3462026-09-11T23:26:20.933Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.89122748Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":77,"vm":"migration_from_base_lifecycle_0"}
3472026-09-11T23:26:20.933Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.891216539Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":8662,"vm":"migration_from_base"}
3482026-09-11T23:26:20.933Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.891489957Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3492026-09-11T23:26:20.933Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.891594125Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3502026-09-11T23:26:20.958Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.916515644Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":24,"vm":"migration_from_base_lifecycle_0"}
3512026-09-11T23:26:20.958Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.916702048Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3522026-09-11T23:26:20.958Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.916958795Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3532026-09-11T23:26:20.958Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.917089933Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8293}
3542026-09-11T23:26:20.958Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.917129859Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3552026-09-11T23:26:20.958Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.917237914Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3562026-09-11T23:26:20.958Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:20.918619664Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3572026-09-11T23:26:21.665Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.64730611Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3582026-09-11T23:26:21.748Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.730834496Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3592026-09-11T23:26:21.748Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.730922913Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-521ab8dd-28a8-4314-b5ea-80cd3939c55f\"]","verb":"destroy","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3602026-09-11T23:26:21.775Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.757379302Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3612026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.757503217Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-854b495b-6550-4ada-8b24-eef5c429f1c4\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","vm":"migration_from_base_lifecycle_0"}
3622026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.775807858Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":858,"vm":"migration_from_base_lifecycle_0"}
3632026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776073121Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","elapsed_milliseconds":4243,"vm":"migration_from_base_lifecycle_0","source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d"}
3642026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776137092Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":858}
3652026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776179572Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"dd5052dc-41a8-4ca2-81a0-24503911c781","source":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","target_id":"c7cfa60a-165e-48a4-a2fb-3314bf6ce50d","elapsed_milliseconds":4243}
3662026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776241019Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":9663}
3672026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776281005Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
3682026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776351549Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3692026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776421151Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3702026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776616261Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3712026-09-11T23:26:21.799Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776728503Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3722026-09-11T23:26:21.800Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776793827Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3732026-09-11T23:26:21.800Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776862788Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3742026-09-11T23:26:21.800Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.776935957Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3752026-09-11T23:26:21.824Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.791086452Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3762026-09-11T23:26:21.824Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.791244051Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-19aac82d-a3a6-4ddd-a1c3-997a8ea15fbe\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3772026-09-11T23:26:21.848Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.811498999Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-19aac82d-a3a6-4ddd-a1c3-997a8ea15fbe\", \"phd-artifacts/phd-clone-7ba42fb8-b30c-4892-b12e-602dd11860ad\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3782026-09-11T23:26:21.848Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.829057276Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-7ba42fb8-b30c-4892-b12e-602dd11860ad\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3792026-09-11T23:26:21.873Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.840595956Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-7ba42fb8-b30c-4892-b12e-602dd11860ad 0B 25.3T 1.30G /phd-artifacts/phd-clone-7ba42fb8-b30c-4892-b12e-602dd11860ad\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3802026-09-11T23:26:21.873Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.841292196Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3812026-09-11T23:26:21.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.841373731Z","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_from_base_and_back","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3822026-09-11T23:26:21.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.841459674Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/903f697d837d6b6f2fbe07ebb851ef9db604f21ea684fb3a5ca2409f41c97c70/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3832026-09-11T23:26:21.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.841530148Z","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/903f697d837d6b6f2fbe07ebb851ef9db604f21ea684fb3a5ca2409f41c97c70/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3842026-09-11T23:26:21.873Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.84161592Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3852026-09-11T23:26:21.903Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 937","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.885400449Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3862026-09-11T23:26:21.927Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.899922637Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":58}
3872026-09-11T23:26:21.927Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.9000347Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3882026-09-11T23:26:21.927Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:21.900744917Z","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":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3892026-09-11T23:26:22.636Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.618221326Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3902026-09-11T23:26:22.682Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.619531671Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 6e4f4958-b25a-413d-9470-cb0565658288, name: \"phd-vm-6e4f4958-b25a-413d-9470-cb0565658288\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 3b0b73a1-76b7-4374-97d0-02185705af92, project_id: b674ca4c-2e13-481e-bec2-5f6ed9f184d7, sled_id: 07cd897d-5f02-43ee-9fe8-b642b5094a5f, sled_serial: \"07cd897d-5f02-43ee-9fe8-b642b5094a5f\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3912026-09-11T23:26:22.682Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.619716722Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3922026-09-11T23:26:22.682Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.619774782Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3932026-09-11T23:26:22.682Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.620964218Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":1}
3942026-09-11T23:26:22.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.621051283Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3952026-09-11T23:26:22.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.621115455Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_from_base_and_back","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3962026-09-11T23:26:22.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.621166341Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3972026-09-11T23:26:22.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.621214352Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3982026-09-11T23:26:22.682Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:22.621265118Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
3992026-09-11T23:26:27.156Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.138194904Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":4516}
4002026-09-11T23:26:27.156Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.138291437Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4012026-09-11T23:26:27.157Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.138490234Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4022026-09-11T23:26:27.157Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.138581026Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4032026-09-11T23:26:27.157Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.138640118Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4042026-09-11T23:26:27.181Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.157510772Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":18}
4052026-09-11T23:26:27.181Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.157667159Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4062026-09-11T23:26:27.181Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.158033394Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4072026-09-11T23:26:27.181Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.158141499Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4082026-09-11T23:26:27.181Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.158191834Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4092026-09-11T23:26:27.207Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.189764845Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":31}
4102026-09-11T23:26:27.207Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.189923596Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4112026-09-11T23:26:27.207Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.190006463Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4568}
4122026-09-11T23:26:27.232Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.190217524Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4132026-09-11T23:26:27.232Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.190272979Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4142026-09-11T23:26:27.232Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.201249174Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":10}
4152026-09-11T23:26:27.232Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.201492365Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4162026-09-11T23:26:27.232Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.201598036Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4172026-09-11T23:26:27.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.234049894Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":32}
4182026-09-11T23:26:27.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.234324725Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4192026-09-11T23:26:27.256Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.234381352Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4202026-09-11T23:26:27.280Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.244874209Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":10}
4212026-09-11T23:26:27.280Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.245144381Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4222026-09-11T23:26:27.280Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.24524897Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4232026-09-11T23:26:27.305Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.277563218Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":32}
4242026-09-11T23:26:27.305Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.27789644Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4252026-09-11T23:26:27.305Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.278013843Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4262026-09-11T23:26:27.329Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.288541235Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":10}
4272026-09-11T23:26:27.329Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.28878094Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4282026-09-11T23:26:27.329Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.288883605Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4292026-09-11T23:26:27.355Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.321997039Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":33}
4302026-09-11T23:26:27.355Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.322321444Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4312026-09-11T23:26:27.355Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.322432875Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4322026-09-11T23:26:27.355Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.333083832Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":10}
4332026-09-11T23:26:27.355Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.33339425Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4342026-09-11T23:26:27.355Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.333503698Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4352026-09-11T23:26:27.384Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.366419488Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":32}
4362026-09-11T23:26:27.409Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.366760865Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4372026-09-11T23:26:27.409Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.366888347Z","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":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4382026-09-11T23:26:27.409Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.377674379Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":10}
4392026-09-11T23:26:27.410Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.377866103Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4402026-09-11T23:26:27.410Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.377927049Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4412026-09-11T23:26:27.434Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.410868916Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":32}
4422026-09-11T23:26:27.434Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.411011436Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4432026-09-11T23:26:27.434Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.411063615Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4442026-09-11T23:26:27.458Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.421544591Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":10}
4452026-09-11T23:26:27.458Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.421706278Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4462026-09-11T23:26:27.458Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.421758306Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4472026-09-11T23:26:27.482Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.45448734Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":32}
4482026-09-11T23:26:27.482Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.45459809Z","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"}
4492026-09-11T23:26:27.482Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.454680246Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-09-11T23:26:27.482Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.454732795Z","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"}
4512026-09-11T23:26:27.482Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.454799372Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4522026-09-11T23:26:27.482Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.454850649Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","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"}
4532026-09-11T23:26:27.482Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.454925511Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-09-11T23:26:27.515Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.497263857Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4552026-09-11T23:26:27.539Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.510095782Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":55}
4562026-09-11T23:26:27.539Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.510207634Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
4572026-09-11T23:26:27.539Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.510283177Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"08b8c1d5-7c0d-43d1-8dfe-95a960e60033","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
4582026-09-11T23:26:27.539Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.510350986Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
4592026-09-11T23:26:27.539Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:27.510931898Z","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_and_back_lifecycle_0","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
4602026-09-11T23:26:28.067Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:28.049509486Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: edf8e04b-f97a-4fa7-a25c-df4c05420882, name: \"phd-vm-edf8e04b-f97a-4fa7-a25c-df4c05420882\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 3b0b73a1-76b7-4374-97d0-02185705af92, project_id: b674ca4c-2e13-481e-bec2-5f6ed9f184d7, sled_id: d3d068a8-fd51-4438-a5e6-8deed5a2a25d, sled_serial: \"d3d068a8-fd51-4438-a5e6-8deed5a2a25d\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
4612026-09-11T23:26:28.068Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:28.049727269Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"08b8c1d5-7c0d-43d1-8dfe-95a960e60033","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
4622026-09-11T23:26:30.340Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:30.322200275Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
4632026-09-11T23:26:32.325Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.307626014Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
4642026-09-11T23:26:32.325Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.307765268Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4257,"migration_id":"08b8c1d5-7c0d-43d1-8dfe-95a960e60033","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
4652026-09-11T23:26:32.349Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.3103453Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4662026-09-11T23:26:32.349Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.310552103Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4672026-09-11T23:26:32.349Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.310615363Z","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":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4682026-09-11T23:26:32.349Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.312541385Z","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":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
4692026-09-11T23:26:32.408Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.391003683Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":80}
4702026-09-11T23:26:32.432Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.391350902Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"6e4f4958-b25a-413d-9470-cb0565658288","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","elapsed_milliseconds":10490}
4712026-09-11T23:26:32.433Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.391523499Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":80}
4722026-09-11T23:26:32.433Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.391891267Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4732026-09-11T23:26:32.433Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.392005734Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4742026-09-11T23:26:32.457Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.421025167Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":29}
4752026-09-11T23:26:32.457Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.421205377Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__BASE_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762026-09-11T23:26:32.457Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.421352544Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772026-09-11T23:26:32.457Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.421402946Z","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_from_base_and_back_lifecycle_1","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4782026-09-11T23:26:32.457Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.421465765Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/903f697d837d6b6f2fbe07ebb851ef9db604f21ea684fb3a5ca2409f41c97c70/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-09-11T23:26:32.457Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.421519577Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/903f697d837d6b6f2fbe07ebb851ef9db604f21ea684fb3a5ca2409f41c97c70/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-09-11T23:26:32.457Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.421586341Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4812026-09-11T23:26:32.487Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 940","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.46486155Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4822026-09-11T23:26:32.511Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.478259888Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":56}
4832026-09-11T23:26:32.512Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.478343447Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
4842026-09-11T23:26:32.512Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.478411516Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"13277102-bb2a-4d39-b37b-e503acbcae1b","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
4852026-09-11T23:26:32.512Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.478473534Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
4862026-09-11T23:26:32.512Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:32.479075465Z","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":"migration_from_base_and_back_lifecycle_1","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
4872026-09-11T23:26:33.319Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:33.301662472Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 7f9e6603-3084-43c6-9ae9-efae79eec333, name: \"phd-vm-7f9e6603-3084-43c6-9ae9-efae79eec333\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 3b0b73a1-76b7-4374-97d0-02185705af92, project_id: b674ca4c-2e13-481e-bec2-5f6ed9f184d7, sled_id: bdb75fda-ecf8-4a5b-bf97-a16eddb2cee9, sled_serial: \"bdb75fda-ecf8-4a5b-bf97-a16eddb2cee9\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
4882026-09-11T23:26:33.345Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:33.301840058Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"13277102-bb2a-4d39-b37b-e503acbcae1b","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
4892026-09-11T23:26:35.630Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:35.612569162Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7894}}"}
4902026-09-11T23:26:36.969Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:36.951576352Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
4912026-09-11T23:26:36.969Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:36.951655172Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3649,"migration_id":"13277102-bb2a-4d39-b37b-e503acbcae1b","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
4922026-09-11T23:26:36.993Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:36.954202973Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4932026-09-11T23:26:36.993Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:36.954505387Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4942026-09-11T23:26:36.993Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:36.95457052Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
4952026-09-11T23:26:36.993Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:36.955924304Z","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":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0"}
4962026-09-11T23:26:37.059Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.041358886Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":86}
4972026-09-11T23:26:37.083Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.041610473Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","elapsed_milliseconds":9530,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
4982026-09-11T23:26:37.083Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.041688521Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":87}
4992026-09-11T23:26:37.083Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.041741331Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":9531,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source":"migration_from_base_and_back","source_id":"6e4f4958-b25a-413d-9470-cb0565658288","target_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882"}
5002026-09-11T23:26:37.083Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.041997888Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5012026-09-11T23:26:37.083Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.0421204Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5022026-09-11T23:26:37.108Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.075571275Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":33}
5032026-09-11T23:26:37.108Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.075721099Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5042026-09-11T23:26:37.108Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.075866004Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5052026-09-11T23:26:37.108Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.075955363Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5062026-09-11T23:26:37.108Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.076193435Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5072026-09-11T23:26:37.108Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.076297111Z","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"}
5082026-09-11T23:26:37.108Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.076435123Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-09-11T23:26:37.139Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 942","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.121091525Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5102026-09-11T23:26:37.163Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.135167066Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":59}
5112026-09-11T23:26:37.163Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.135266224Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5122026-09-11T23:26:37.163Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.135351236Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"979f872a-0a7a-4404-938c-f5024acd56fd","timeout_duration":"45s","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5132026-09-11T23:26:37.163Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.135430756Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5142026-09-11T23:26:37.163Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.136036275Z","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":"migration_from_base_and_back_lifecycle_2","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5152026-09-11T23:26:37.875Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.856918298Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1, name: \"phd-vm-4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 3b0b73a1-76b7-4374-97d0-02185705af92, project_id: b674ca4c-2e13-481e-bec2-5f6ed9f184d7, sled_id: 4ab985fd-4bf5-4e98-b9e3-241d1393b808, sled_serial: \"4ab985fd-4bf5-4e98-b9e3-241d1393b808\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5162026-09-11T23:26:37.875Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:37.857132514Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"979f872a-0a7a-4404-938c-f5024acd56fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5172026-09-11T23:26:40.162Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.143910007Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7941}}"}
5182026-09-11T23:26:40.379Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.36065355Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5192026-09-11T23:26:40.379Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.360731979Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":2503,"migration_id":"979f872a-0a7a-4404-938c-f5024acd56fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5202026-09-11T23:26:40.404Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.362756298Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5212026-09-11T23:26:40.404Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.363000391Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5222026-09-11T23:26:40.404Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.363073319Z","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":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5232026-09-11T23:26:40.404Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.364529942Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1"}
5242026-09-11T23:26:40.460Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.442067957Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":78}
5252026-09-11T23:26:40.484Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.442268477Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","elapsed_milliseconds":7963,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
5262026-09-11T23:26:40.485Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.442387613Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":7963,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_1","source":"migration_from_base_and_back_lifecycle_0","source_id":"edf8e04b-f97a-4fa7-a25c-df4c05420882","target_id":"7f9e6603-3084-43c6-9ae9-efae79eec333"}
5272026-09-11T23:26:40.485Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.442554349Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":79}
5282026-09-11T23:26:40.485Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.442899855Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5292026-09-11T23:26:40.485Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.443024641Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5302026-09-11T23:26:40.510Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.474402643Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":31}
5312026-09-11T23:26:40.510Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.474599847Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5322026-09-11T23:26:40.510Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.474800998Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5332026-09-11T23:26:40.510Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.474933469Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":17855}
5342026-09-11T23:26:40.510Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.474970209Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5352026-09-11T23:26:40.510Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.475122718Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5362026-09-11T23:26:40.510Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:40.476508997Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5372026-09-11T23:26:41.217Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.19875116Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5382026-09-11T23:26:41.302Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.284456274Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5392026-09-11T23:26:41.302Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.284600678Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-7ba42fb8-b30c-4892-b12e-602dd11860ad\"]","verb":"destroy","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5402026-09-11T23:26:41.331Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.313536128Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5412026-09-11T23:26:41.331Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.31360549Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-19aac82d-a3a6-4ddd-a1c3-997a8ea15fbe\"]","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2"}
5422026-09-11T23:26:41.356Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.331092049Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":856}
5432026-09-11T23:26:41.356Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.331372842Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":856}
5442026-09-11T23:26:41.356Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.33137161Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","elapsed_milliseconds":4195,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5452026-09-11T23:26:41.356Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.331503961Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5462026-09-11T23:26:41.356Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.33150362Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4195,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_2","source":"migration_from_base_and_back_lifecycle_1","source_id":"7f9e6603-3084-43c6-9ae9-efae79eec333","target_id":"4cd23da8-84b0-4d71-8a5c-c6e2ff3582d1"}
5472026-09-11T23:26:41.356Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.331553054Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5482026-09-11T23:26:41.356Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.331587499Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":19553}
5492026-09-11T23:26:41.356Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 89.64s
5502026-09-11T23:26:41.356Z
5512026-09-11T23:26:41.357Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-09-11T23:26:41.333795867Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5522026-09-11T23:26:41.476Z
5532026-09-11T23:26:41.500Zreal 1:32.293072491
5542026-09-11T23:26:41.501Zuser 50.317932540
5552026-09-11T23:26:41.501Zsys 21.660071839
5562026-09-11T23:26:41.501Ztrap 0.007012786
5572026-09-11T23:26:41.501Ztflt 0.005165606
5582026-09-11T23:26:41.501Zdflt 0.001627463
5592026-09-11T23:26:41.501Zkflt 0.000000000
5602026-09-11T23:26:41.501Zlock 3:34:22.398666309
5612026-09-11T23:26:41.501Zslp 4:09.011129524
5622026-09-11T23:26:41.501Zlat 2.120854253
5632026-09-11T23:26:41.501Zstop 48.839600365
5642026-09-11T23:26:41.501Z+ failcount=0
5652026-09-11T23:26:41.501Z+ set -e
5662026-09-11T23:26:41.501Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
5672026-09-11T23:26:41.526ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5682026-09-11T23:26:41.526Za ./ 0K
5692026-09-11T23:26:41.526Za ./phd_tests::migrate::from_base::serial_history/ 0K
5702026-09-11T23:26:41.526Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 159K
5712026-09-11T23:26:41.526Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
5722026-09-11T23:26:41.526Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
5732026-09-11T23:26:41.526Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 165K
5742026-09-11T23:26:41.526Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
5752026-09-11T23:26:41.526Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
5762026-09-11T23:26:41.526Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 158K
5772026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
5782026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
5792026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 164K
5802026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
5812026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
5822026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 157K
5832026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
5842026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
5852026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 268K
5862026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5872026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 268K
5882026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5892026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 164K
5902026-09-11T23:26:41.527Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5912026-09-11T23:26:41.527Z+ exitcode=0
5922026-09-11T23:26:41.527Z+ '[' 0 -eq 0 ']'
5932026-09-11T23:26:41.527Z+ echo
5942026-09-11T23:26:41.527Z+ echo 'ALL TESTS PASSED'
5952026-09-11T23:26:41.527Z+ echo
5962026-09-11T23:26:41.527Z
5972026-09-11T23:26:41.527ZALL TESTS PASSED
5982026-09-11T23:26:41.527Z
5992026-09-11T23:26:41.527Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6002026-09-11T23:26:41.527Z+ read
6012026-09-11T23:26:41.527Z+ exit 0
6022026-09-11T23:26:41.527Zprocess exited: duration 163788 ms, exit code 0
 
6032026-09-11T23:26:41.601Zfound 2 output files
6042026-09-11T23:26:41.601Zuploading: /tmp/phd-runner.log (184366 bytes)
6052026-09-11T23:26:42.788Zuploaded: /tmp/phd-runner.log
6062026-09-11T23:26:42.813Zuploading: /tmp/phd-tmp-files.tar.gz (133441 bytes)
6072026-09-11T23:26:43.970Zuploaded: /tmp/phd-tmp-files.tar.gz