01M476P5MX2FKA8GKXQAB59CVV: 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: 01M476PHHX55203K71KS2C3PTV

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12026-10-05T23:46:19.216Zjob dependencies complete; ready to run (waiting for 11 m 45 s)
22026-10-06T00:07:51.607Zjob assigned to worker 01M478DFYHJZ1SKQ3QG38ECHRB [factory edgar, gimlet/BRM42220010/1698] (queued for 21 m 32 s)
32026-10-06T00:07:52.594Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
42026-10-06T00:07:52.640Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
52026-10-06T00:07:52.640Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
62026-10-06T00:07:52.685Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
72026-10-06T00:07:52.686Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
82026-10-06T00:08:01.103Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
92026-10-06T00:08:01.128Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
102026-10-06T00:08:01.153Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
112026-10-06T00:08:01.153Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
122026-10-06T00:08:14.621Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
132026-10-06T00:08:14.621Zdownloading input: /input/phd-build/out/propolis-tests-debug.tar.gz
142026-10-06T00:08:24.513Zdownloaded input: /input/phd-build/out/propolis-tests-debug.tar.gz
 
152026-10-06T00:08:24.513Zstarting task 0: "setup"
162026-10-06T00:08:24.537Z++ uname -s
172026-10-06T00:08:24.537Z+ kern=SunOS
182026-10-06T00:08:24.537Z+ build_user=build
192026-10-06T00:08:24.537Z+ build_uid=12345
202026-10-06T00:08:24.537Z+ work_dir=/work
212026-10-06T00:08:24.537Z+ input_dir=/input
222026-10-06T00:08:24.537Z+ [[ 0 == 12345 ]]
232026-10-06T00:08:24.537Z+ case "$kern" in
242026-10-06T00:08:24.537Z+ groupadd -g 12345 build
252026-10-06T00:08:24.560Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
262026-10-06T00:08:26.548Z+ zfs create -o mountpoint=/work rpool/work
272026-10-06T00:08:26.770Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
282026-10-06T00:08:26.793Z+ home_fs=
292026-10-06T00:08:26.793Z+ [[ '' == autofs ]]
302026-10-06T00:08:26.793Z+ mkdir -p /home/build
312026-10-06T00:08:26.793Z+ chown build:build /home/build /work
322026-10-06T00:08:28.783Z+ chmod 0700 /home/build /work
332026-10-06T00:08:28.808Zprocess exited: duration 4275 ms, exit code 0
 
342026-10-06T00:08:28.856Zstarting task 1: "authentication"
352026-10-06T00:08:28.924Zprocess exited: duration 68 ms, exit code 0
 
362026-10-06T00:08:28.972Zstarting task 2: "build"
372026-10-06T00:08:28.997Z+ indir=/input
382026-10-06T00:08:28.997Z+ indir_suffix='phd-build/out/*.tar.gz'
392026-10-06T00:08:28.997Z+ phddir=/work/phd-test
402026-10-06T00:08:28.997Z+ disks=($(pilot local disk list -H -o type,disk | grep -v 'M.2' | cut -f 2))
412026-10-06T00:08:29.021Z++ pilot local disk list -H -o type,disk
422026-10-06T00:08:29.021Z++ grep -v M.2
432026-10-06T00:08:29.021Z++ cut -f 2
442026-10-06T00:08:29.071Z+ pfexec zpool create -f phd-artifacts c8t0014EE81000BC42Fd0 c9t0014EE81000BC3B1d0 c10t0014EE81000BC514d0 c11t0014EE81000BC3B6d0 c4t0014EE81000BC3ACd0 c3t0014EE81000BC430d0 c2t0014EE81000BC16Fd0 c6t0014EE81000BC544d0 c5t0014EE81000BC429d0
452026-10-06T00:08:31.643Z+ artifactdir=/phd-artifacts
462026-10-06T00:08:31.643Z+ banner Inputs
472026-10-06T00:08:31.692Z ###
482026-10-06T00:08:31.692Z # # # ##### # # ##### ####
492026-10-06T00:08:31.692Z # ## # # # # # # #
502026-10-06T00:08:31.692Z # # # # # # # # # ####
512026-10-06T00:08:31.692Z # # # # ##### # # # #
522026-10-06T00:08:31.692Z # # ## # # # # # #
532026-10-06T00:08:31.692Z ### # # # #### # ####
542026-10-06T00:08:31.693Z
552026-10-06T00:08:31.693Z+ find /input -ls
562026-10-06T00:08:31.693Z 34 1 drwxr-xr-x 3 root root 3 Oct 6 00:07 /input
572026-10-06T00:08:31.693Z 2 1 drwxr-xr-x 3 root root 3 Oct 6 00:07 /input/phd-build
582026-10-06T00:08:31.693Z 3 2 drwxr-xr-x 2 root root 8 Oct 6 00:08 /input/phd-build/out
592026-10-06T00:08:31.693Z 640 223292 -rw-r--r-- 1 root root 228595938 Oct 6 00:08 /input/phd-build/out/propolis-tests-debug.tar.gz
602026-10-06T00:08:31.693Z 128 2 -rw-r--r-- 1 root root 2573 Oct 6 00:07 /input/phd-build/out/phd-run-with-args.sh
612026-10-06T00:08:31.693Z 256 187948 -rw-r--r-- 1 root root 192361930 Oct 6 00:08 /input/phd-build/out/phd-runner.tar.gz
622026-10-06T00:08:31.693Z 512 261787 -rw-r--r-- 1 root root 268033379 Oct 6 00:08 /input/phd-build/out/propolis-server-debug.tar.gz
632026-10-06T00:08:31.693Z 129 1 -rw-r--r-- 1 root root 65 Oct 6 00:07 /input/phd-build/out/phd-runner.sha256.txt
642026-10-06T00:08:31.693Z 384 1 -rw-r--r-- 1 root root 65 Oct 6 00:08 /input/phd-build/out/propolis-server-debug.sha256.txt
652026-10-06T00:08:31.693Z+ rm -rf /work/phd-test
662026-10-06T00:08:31.693Z+ mkdir /work/phd-test
672026-10-06T00:08:31.693Z+ for p in $indir/$indir_suffix
682026-10-06T00:08:31.693Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
692026-10-06T00:08:47.081ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
702026-10-06T00:08:47.081Zx phd-runner, 737219344 bytes, 1439882 tape blocks
712026-10-06T00:08:47.081Zx artifacts.toml, 548 bytes, 2 tape blocks
722026-10-06T00:08:47.104Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
732026-10-06T00:08:51.595Z+ for f in $(tar tf "$p")
742026-10-06T00:08:51.595Z+ chmod +x /work/phd-test/phd-runner
752026-10-06T00:08:51.618Z+ for f in $(tar tf "$p")
762026-10-06T00:08:51.618Z+ chmod +x /work/phd-test/artifacts.toml
772026-10-06T00:08:51.618Z+ for p in $indir/$indir_suffix
782026-10-06T00:08:51.618Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
792026-10-06T00:09:10.325ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
802026-10-06T00:09:10.326Zx propolis-server, 1074460728 bytes, 2098557 tape blocks
812026-10-06T00:09:10.349Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
822026-10-06T00:09:17.228Z+ for f in $(tar tf "$p")
832026-10-06T00:09:17.228Z+ chmod +x /work/phd-test/propolis-server
842026-10-06T00:09:17.251Z+ for p in $indir/$indir_suffix
852026-10-06T00:09:17.251Z+ tar xzvf /input/phd-build/out/propolis-tests-debug.tar.gz -C /work/phd-test
862026-10-06T00:09:34.004ZDecompressing '/input/phd-build/out/propolis-tests-debug.tar.gz' with '/usr/bin/gzcat'...
872026-10-06T00:09:34.004Zx target/debug/deps/propolis-16accc46ec7fe886, 916130272 bytes, 1789317 tape blocks
882026-10-06T00:09:34.028Z++ tar tf /input/phd-build/out/propolis-tests-debug.tar.gz
892026-10-06T00:09:39.571Z+ for f in $(tar tf "$p")
902026-10-06T00:09:39.571Z+ chmod +x /work/phd-test/target/debug/deps/propolis-16accc46ec7fe886
912026-10-06T00:09:39.595Z+ ls /work/phd-test
922026-10-06T00:09:39.595Zartifacts.toml
932026-10-06T00:09:39.595Zphd-runner
942026-10-06T00:09:39.595Zpropolis-server
952026-10-06T00:09:39.595Ztarget
962026-10-06T00:09:39.595Z+ banner Setup
972026-10-06T00:09:39.595Z #####
982026-10-06T00:09:39.595Z# # ###### ##### # # #####
992026-10-06T00:09:39.595Z# # # # # # #
1002026-10-06T00:09:39.595Z ##### ##### # # # # #
1012026-10-06T00:09:39.595Z # # # # # #####
1022026-10-06T00:09:39.596Z# # # # # # #
1032026-10-06T00:09:39.596Z ##### ###### # #### #
1042026-10-06T00:09:39.596Z
1052026-10-06T00:09:39.596Z+ tmpdir=/tmp/propolis-phd
1062026-10-06T00:09:39.596Z+ '[' '!' -d /tmp/propolis-phd ']'
1072026-10-06T00:09:39.596Z+ mkdir /tmp/propolis-phd
1082026-10-06T00:09:39.596Z+ pfexec /usr/lib/rsrvrctl -s 4096
1092026-10-06T00:09:40.044Z+ banner Tests
1102026-10-06T00:09:40.068Z#######
1112026-10-06T00:09:40.068Z # ###### #### ##### ####
1122026-10-06T00:09:40.068Z # # # # #
1132026-10-06T00:09:40.068Z # ##### #### # ####
1142026-10-06T00:09:40.068Z # # # # #
1152026-10-06T00:09:40.068Z # # # # # # #
1162026-10-06T00:09:40.068Z # ###### #### # ####
1172026-10-06T00:09:40.068Z
1182026-10-06T00:09:40.068Z+ runner=/work/phd-test/phd-runner
1192026-10-06T00:09:40.068Z+ artifacts=/work/phd-test/artifacts.toml
1202026-10-06T00:09:40.068Z+ propolis=/work/phd-test/propolis-server
1212026-10-06T00:09:40.068Z+ ls /work/phd-test/phd-runner
1222026-10-06T00:09:40.069Z/work/phd-test/phd-runner
1232026-10-06T00:09:40.069Z+ ls /work/phd-test/artifacts.toml
1242026-10-06T00:09:40.069Z/work/phd-test/artifacts.toml
1252026-10-06T00:09:40.069Z+ ls /work/phd-test/propolis-server
1262026-10-06T00:09:40.069Z/work/phd-test/propolis-server
1272026-10-06T00:09:40.069Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1282026-10-06T00:09:40.069Z+ set +e
1292026-10-06T00:09:40.069Z+ RUST_BACKTRACE=1
1302026-10-06T00:09:40.069Z+ RUST_LOG=info,phd=debug
1312026-10-06T00:09:40.069Z+ ptime -m pfexec /work/phd-test/phd-runner --emit-bunyan run --propolis-server-cmd /work/phd-test/propolis-server --crucible-downstairs-commit auto --artifact-toml-path /work/phd-test/artifacts.toml --tmp-directory /tmp/propolis-phd --artifact-directory /phd-artifacts --include-filter phd_tests::migrate::from_base --base-propolis-branch master
1322026-10-06T00:09:40.069Z+ tee /tmp/phd-runner.log
1332026-10-06T00:09:40.267Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:40.239121405Z","target":"phd_runner","line":36,"file":"phd-tests/runner/src/main.rs","runner_args":"ProcessArgs { command: Run(RunOptions { propolis_server_cmd: \"/work/phd-test/propolis-server\", base_propolis_branch: Some(\"master\"), base_propolis_commit: None, base_propolis_cmd: None, crucible_downstairs_cmd: None, crucible_downstairs_commit: Some(Auto), tmp_directory: \"/tmp/propolis-phd\", artifact_directory: Some(\"/phd-artifacts\"), output_mode: TmpFile, default_guest_cpus: 2, default_guest_memory_mib: 512, artifact_toml_path: \"/work/phd-test/artifacts.toml\", default_guest_artifact: \"alpine\", default_bootrom_artifact: \"ovmf\", include_filter: [\"phd_tests::migrate::from_base\"], exclude_filter: [], max_buildomat_wait_secs: 1200, manual_stop_on_failure: false }), disable_ansi: false, emit_bunyan: true }"}
1342026-10-06T00:09:40.290Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:40.266736027Z","target":"phd_framework::artifacts::store","line":219,"file":"phd-tests/framework/src/artifacts/store.rs","store":"Store { local_dir: \"/phd-artifacts\", artifacts: {\"alpine\": Mutex { data: StoredArtifact { description: Artifact { filename: \"alpine.iso\", kind: GuestOs(Alpine), source: RemoteServer { sha256: \"ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1\" }, untar: None }, cached_path: None } }, \"ovmf\": Mutex { data: StoredArtifact { description: Artifact { filename: \"OVMF_CODE.fd\", kind: Bootrom, source: Buildomat(BuildomatArtifact { repo: Repo(\"oxidecomputer/edk2\"), series: Series(\"image_debug\"), commit: Commit(\"bf64f45b1a58e69d126a3c6ca1e4512c88668132\"), sha256: \"740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448\" }), untar: None }, cached_path: None } }}, downloader: DownloadConfig { timeout: 600s, buildomat_backoff: ExponentialBackoff { current_interval: 1s, initial_interval: 1s, randomization_factor: 0.5, multiplier: 1.5, max_interval: 60s, start_time: Instant { tv_sec: 254, tv_nsec: 191081088 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1352026-10-06T00:09:40.290Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:40.267290268Z","target":"phd_framework::artifacts::store","line":227,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1362026-10-06T00:09:40.290Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:40.269076473Z","target":"phd_framework::artifacts::store","line":311,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"ad8a31742adc45e925e63443a5b43c8e30604022"}
1372026-10-06T00:09:40.314Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:40.274139119Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/ad8a31742adc45e925e63443a5b43c8e30604022/crucible-nightly.sha256.txt","timeout":"600s"}
1382026-10-06T00:09:40.544Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:40.526034077Z","target":"phd_framework::artifacts::store","line":248,"file":"phd-tests/framework/src/artifacts/store.rs"}
1392026-10-06T00:09:41.179Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.16060828Z","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/77848924fedc3e1439efb055f5459714c2bb322c/propolis-server.sha256.txt"}
1402026-10-06T00:09:41.360Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.341521324Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1412026-10-06T00:09:41.383Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.342368359Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1422026-10-06T00:09:41.383Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.344150016Z","target":"phd_runner::execute","line":83,"file":"phd-tests/runner/src/execute.rs"}
1432026-10-06T00:09:41.383Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.344788497Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
1442026-10-06T00:09:41.383Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.344831548Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1452026-10-06T00:09:41.383Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.344869129Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1462026-10-06T00:09:41.383Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.345806516Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
1472026-10-06T00:09:41.383Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.347651794Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
1482026-10-06T00:09:41.383Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.349674087Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/bf64f45b1a58e69d126a3c6ca1e4512c88668132/OVMF_CODE.fd","timeout":"600s","path":"phd_tests::migrate::from_base::serial_history"}
1492026-10-06T00:09:41.912Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.893656065Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::serial_history"}
1502026-10-06T00:09:41.935Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:41.906494861Z","target":"phd_framework::artifacts::store","line":614,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::serial_history"}
1512026-10-06T00:09:48.494Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.475494878Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::serial_history"}
1522026-10-06T00:09:48.494Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.475632619Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::serial_history"}
1532026-10-06T00:09:48.517Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.49297386Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 4.60M 25.3T 2M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
1542026-10-06T00:09:48.517Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.494946049Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-797a8b76-faaa-46df-a842-19599555f9bd\"]","path":"phd_tests::migrate::from_base::serial_history"}
1552026-10-06T00:09:48.541Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.515755422Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-797a8b76-faaa-46df-a842-19599555f9bd\", \"phd-artifacts/phd-clone-90151d78-e482-4371-86a3-d369022b3410\"]","path":"phd_tests::migrate::from_base::serial_history"}
1562026-10-06T00:09:48.564Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.532333637Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-90151d78-e482-4371-86a3-d369022b3410\"]","verb":"list","path":"phd_tests::migrate::from_base::serial_history"}
1572026-10-06T00:09:48.564Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.543281579Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-90151d78-e482-4371-86a3-d369022b3410 0B 25.3T 49.0M /phd-artifacts/phd-clone-90151d78-e482-4371-86a3-d369022b3410\n","path":"phd_tests::migrate::from_base::serial_history"}
1582026-10-06T00:09:48.587Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.547425654Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1592026-10-06T00:09:48.588Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.548037704Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::serial_history"}
1602026-10-06T00:09:48.588Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.548127304Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/4bf8fc6099e34afbdcfdef6b4e86494863090e3d681d8eb37a4e182353d1c2dd/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1612026-10-06T00:09:48.588Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:09:48.548201665Z","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/77848924fedc3e1439efb055f5459714c2bb322c/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::serial_history"}
1622026-10-06T00:10:05.692Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:05.672681339Z","target":"phd_framework::artifacts::store","line":160,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/4bf8fc6099e34afbdcfdef6b4e86494863090e3d681d8eb37a4e182353d1c2dd/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
1632026-10-06T00:10:05.692Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:05.672768464Z","target":"phd_framework::artifacts::store","line":514,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::serial_history"}
1642026-10-06T00:10:30.790Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:30.769046942Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/4bf8fc6099e34afbdcfdef6b4e86494863090e3d681d8eb37a4e182353d1c2dd/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
1652026-10-06T00:10:30.790Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:30.769171919Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
1662026-10-06T00:10:30.973Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 917","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:30.95205367Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
1672026-10-06T00:10:30.997Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:30.966613127Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1682026-10-06T00:10:31.021Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:30.977673624Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1692026-10-06T00:10:31.021Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:30.981609835Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":42434}
1702026-10-06T00:10:31.512Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.491328727Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1712026-10-06T00:10:31.557Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.495889983Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: e2207d1a-2dfa-4148-b261-58384c109771, name: \"phd-vm-e2207d1a-2dfa-4148-b261-58384c109771\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 95d1a759-062d-4774-bf36-301d49b34a81, project_id: d25b4899-63cd-4611-9a3d-06912dbe1abe, sled_id: 4f03a5f3-fe69-4034-9d53-ff83eab2bf6e, sled_serial: \"4f03a5f3-fe69-4034-9d53-ff83eab2bf6e\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1722026-10-06T00:10:31.557Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.496045638Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1732026-10-06T00:10:31.557Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.496104329Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1742026-10-06T00:10:31.557Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.498613024Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":2,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1752026-10-06T00:10:31.557Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.499301068Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1762026-10-06T00:10:31.557Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.499385719Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_serial_history_base","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history"}
1772026-10-06T00:10:31.557Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.499442396Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
1782026-10-06T00:10:31.557Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.499525664Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1792026-10-06T00:10:31.557Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:31.499594244Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1802026-10-06T00:10:36.064Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.042975777Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4543,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1812026-10-06T00:10:36.065Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.043082539Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
1822026-10-06T00:10:36.635Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.046914013Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1832026-10-06T00:10:36.635Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.046982203Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1842026-10-06T00:10:36.635Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.047035393Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1852026-10-06T00:10:36.742Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.071611106Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":24,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1862026-10-06T00:10:36.742Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.071765989Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
1872026-10-06T00:10:36.742Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.072192839Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
1882026-10-06T00:10:36.742Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.072260757Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1892026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.072311904Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1902026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.104904604Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":32,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1912026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.105052725Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
1922026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.105131354Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4605}
1932026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.105429068Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1942026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.106024136Z","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":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1952026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.116549116Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":10,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1962026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.116811293Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1972026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.116916553Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1982026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.149123892Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":32,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
1992026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.149376341Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2002026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.149479196Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2012026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.160364118Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":10,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2022026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.160685497Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2032026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.16080312Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2042026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.194031032Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":33,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2052026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.20425843Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_serial_history_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::serial_history"}
2062026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.204385521Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2072026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.204437579Z","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_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2082026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.20490723Z","target":"phd_framework::artifacts::store","line":56,"file":"phd-tests/framework/src/artifacts/store.rs","sha256":"None","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2092026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.204973876Z","target":"phd_framework::artifacts::store","line":69,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2102026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.205027948Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
2112026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.205097671Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
2122026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 918","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.249536705Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
2132026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.261995851Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":57}
2142026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.262088957Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0"}
2152026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.262536375Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"52cd67fe-ebee-4602-ac36-b023b402e08d","timeout_duration":"45s","source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0"}
2162026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.262609925Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","vm":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2172026-10-06T00:10:36.743Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:36.2631613Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","vm":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2182026-10-06T00:10:37.024Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:37.00220661Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: cc19ed4d-6347-4c26-8861-e8babf9fb04c, name: \"phd-vm-cc19ed4d-6347-4c26-8861-e8babf9fb04c\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 95d1a759-062d-4774-bf36-301d49b34a81, project_id: d25b4899-63cd-4611-9a3d-06912dbe1abe, sled_id: bc120c99-99e5-47e3-9af3-addf158e583e, sled_serial: \"bc120c99-99e5-47e3-9af3-addf158e583e\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","vm":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2192026-10-06T00:10:37.048Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:37.0036151Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","source":"migration_serial_history_base","migration_id":"52cd67fe-ebee-4602-ac36-b023b402e08d","target":"migration_serial_history_base_lifecycle_0"}
2202026-10-06T00:10:39.545Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.523284265Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7756}}"}
2212026-10-06T00:10:39.847Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.822918753Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0"}
2222026-10-06T00:10:39.847Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.823002321Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","elapsed_milliseconds":2819,"source":"migration_serial_history_base","migration_id":"52cd67fe-ebee-4602-ac36-b023b402e08d","target":"migration_serial_history_base_lifecycle_0"}
2232026-10-06T00:10:39.871Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.826307245Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2242026-10-06T00:10:39.871Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.8292432Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2252026-10-06T00:10:39.929Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.907804053Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":79,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2262026-10-06T00:10:39.953Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.908031114Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":8941,"vm_id":"e2207d1a-2dfa-4148-b261-58384c109771"}
2272026-10-06T00:10:39.953Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.910768222Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2282026-10-06T00:10:39.953Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.911381013Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2292026-10-06T00:10:39.953Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.912053889Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8420}
2302026-10-06T00:10:39.953Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.913012626Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2312026-10-06T00:10:39.953Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.913491574Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
2322026-10-06T00:10:39.953Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:39.913590792Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2332026-10-06T00:10:40.576Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.553289109Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2342026-10-06T00:10:40.661Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.638995706Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2352026-10-06T00:10:40.661Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.639085246Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-90151d78-e482-4371-86a3-d369022b3410\"]","verb":"destroy","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2362026-10-06T00:10:40.687Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.665045745Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2372026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.665142919Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-797a8b76-faaa-46df-a842-19599555f9bd\"]","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2382026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.683385297Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":772,"vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2392026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.683626094Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":4421,"source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0","vm_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c"}
2402026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.683729019Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"e2207d1a-2dfa-4148-b261-58384c109771","path":"phd_tests::migrate::from_base::serial_history","target_id":"cc19ed4d-6347-4c26-8861-e8babf9fb04c","elapsed_milliseconds":4421,"source":"migration_serial_history_base","target":"migration_serial_history_base_lifecycle_0"}
2412026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.683790074Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":59338}
2422026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.684118397Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":770}
2432026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.684222664Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
2442026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.684268371Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2452026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.684309539Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2462026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.684470835Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2472026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.684575774Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2482026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.68464778Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2492026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.684714517Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2502026-10-06T00:10:40.731Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.684795861Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2512026-10-06T00:10:40.755Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.695278871Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2522026-10-06T00:10:40.755Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.695434566Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-f6955288-dda9-4f08-a8bb-2535bd576f66\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2532026-10-06T00:10:40.755Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.712873261Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-f6955288-dda9-4f08-a8bb-2535bd576f66\", \"phd-artifacts/phd-clone-b4623d6d-99bf-4cc8-90d4-e10e44231145\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2542026-10-06T00:10:40.755Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.729547929Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-b4623d6d-99bf-4cc8-90d4-e10e44231145\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2552026-10-06T00:10:40.778Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.740231148Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-b4623d6d-99bf-4cc8-90d4-e10e44231145 0B 25.3T 1.30G /phd-artifacts/phd-clone-b4623d6d-99bf-4cc8-90d4-e10e44231145\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2562026-10-06T00:10:40.778Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.740948658Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2572026-10-06T00:10:40.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.741016367Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2582026-10-06T00:10:40.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.741093874Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/4bf8fc6099e34afbdcfdef6b4e86494863090e3d681d8eb37a4e182353d1c2dd/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2592026-10-06T00:10:40.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.741159698Z","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/4bf8fc6099e34afbdcfdef6b4e86494863090e3d681d8eb37a4e182353d1c2dd/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2602026-10-06T00:10:40.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.741236835Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2612026-10-06T00:10:40.807Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 927","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.785091892Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2622026-10-06T00:10:40.832Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.799485234Z","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":58}
2632026-10-06T00:10:40.832Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.799620661Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2642026-10-06T00:10:40.832Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:40.800309787Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2652026-10-06T00:10:41.353Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.331016544Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2662026-10-06T00:10:41.397Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.332195588Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 8958cad2-9f76-45ca-b2a9-a022e327bf62, name: \"phd-vm-8958cad2-9f76-45ca-b2a9-a022e327bf62\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 106f953e-fa14-4702-9a6d-0aa9a16b5f24, project_id: 1661a95d-54f5-404b-ba0e-caebaf2af3b2, sled_id: e451a704-382b-4cb2-ba1f-642e0542b8d9, sled_serial: \"e451a704-382b-4cb2-ba1f-642e0542b8d9\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2672026-10-06T00:10:41.397Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.332369568Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2682026-10-06T00:10:41.397Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.332427217Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2692026-10-06T00:10:41.397Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.333271167Z","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","elapsed_milliseconds":0,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2702026-10-06T00:10:41.397Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.333352311Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2712026-10-06T00:10:41.398Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.333409579Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2722026-10-06T00:10:41.398Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.333458362Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2732026-10-06T00:10:41.398Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.333502846Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2742026-10-06T00:10:41.398Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:41.333551308Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2752026-10-06T00:10:45.976Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.953523961Z","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","elapsed_milliseconds":4620,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2762026-10-06T00:10:45.976Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.953620114Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2772026-10-06T00:10:45.999Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.953871169Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2782026-10-06T00:10:46.000Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.953928428Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2792026-10-06T00:10:46.000Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.95397178Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2802026-10-06T00:10:46.000Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.971820963Z","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","elapsed_milliseconds":17,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2812026-10-06T00:10:46.000Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.971961579Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2822026-10-06T00:10:46.000Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.972166498Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2832026-10-06T00:10:46.000Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.972227633Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2842026-10-06T00:10:46.000Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:45.972283259Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2852026-10-06T00:10:46.027Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.005241191Z","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","elapsed_milliseconds":32,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2862026-10-06T00:10:46.027Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.005366679Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
2872026-10-06T00:10:46.051Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.005444747Z","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":4672}
2882026-10-06T00:10:46.051Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.005681265Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2892026-10-06T00:10:46.051Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.005806222Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2902026-10-06T00:10:46.051Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.016247934Z","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","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2912026-10-06T00:10:46.051Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.01649388Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2922026-10-06T00:10:46.051Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.016602015Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2932026-10-06T00:10:46.074Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.049991525Z","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","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2942026-10-06T00:10:46.074Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.050751085Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2952026-10-06T00:10:46.075Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.050824374Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2962026-10-06T00:10:46.098Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.060545961Z","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","elapsed_milliseconds":9,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2972026-10-06T00:10:46.098Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.060802117Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2982026-10-06T00:10:46.098Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.060920381Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
2992026-10-06T00:10:46.121Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.093916153Z","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","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3002026-10-06T00:10:46.121Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.094160767Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3012026-10-06T00:10:46.121Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.094262029Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3022026-10-06T00:10:46.145Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.105121614Z","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","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3032026-10-06T00:10:46.145Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.10543564Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3042026-10-06T00:10:46.145Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.105499611Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3052026-10-06T00:10:46.168Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.137278216Z","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","elapsed_milliseconds":31,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3062026-10-06T00:10:46.168Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.137524192Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3072026-10-06T00:10:46.168Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.137625024Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3082026-10-06T00:10:46.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.148261797Z","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","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3092026-10-06T00:10:46.192Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.148499057Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3102026-10-06T00:10:46.192Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.148598225Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3112026-10-06T00:10:46.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.182479265Z","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","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3122026-10-06T00:10:46.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.182722857Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3132026-10-06T00:10:46.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.182790986Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3142026-10-06T00:10:46.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.193589284Z","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","elapsed_milliseconds":10,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3152026-10-06T00:10:46.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.19392506Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3162026-10-06T00:10:46.238Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.194035389Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3172026-10-06T00:10:46.262Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.227235631Z","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","elapsed_milliseconds":33,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3182026-10-06T00:10:46.262Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.22812667Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3192026-10-06T00:10:46.262Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.228198446Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3202026-10-06T00:10:46.262Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.238153235Z","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","elapsed_milliseconds":9,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3212026-10-06T00:10:46.262Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.238416784Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3222026-10-06T00:10:46.262Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.238521513Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3232026-10-06T00:10:46.736Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.260874354Z","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","elapsed_milliseconds":22,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3242026-10-06T00:10:46.736Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.261121051Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3252026-10-06T00:10:46.736Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.261272398Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3262026-10-06T00:10:46.736Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.261377498Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3272026-10-06T00:10:46.736Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.261499849Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3282026-10-06T00:10:46.736Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.261605079Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3292026-10-06T00:10:46.736Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.261733522Z","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-10-06T00:10:46.780Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 928","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.303522263Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3312026-10-06T00:10:46.781Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.31633007Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":54}
3322026-10-06T00:10:46.781Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.316410543Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3332026-10-06T00:10:46.781Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.316473512Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"14f7e0de-a1f8-4c65-bbd8-08c960bc470a","timeout_duration":"45s","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3342026-10-06T00:10:46.781Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.316536612Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","vm":"migration_from_base_lifecycle_0","source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3352026-10-06T00:10:46.781Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.317094239Z","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":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","vm":"migration_from_base_lifecycle_0","source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3362026-10-06T00:10:46.857Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.83447289Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 9b4e0b07-fd07-49b1-9c6f-315884b5019c, name: \"phd-vm-9b4e0b07-fd07-49b1-9c6f-315884b5019c\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: 106f953e-fa14-4702-9a6d-0aa9a16b5f24, project_id: 1661a95d-54f5-404b-ba0e-caebaf2af3b2, sled_id: b61fe4e1-8788-46cb-a7f9-dc2e8767248b, sled_serial: \"b61fe4e1-8788-46cb-a7f9-dc2e8767248b\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","vm":"migration_from_base_lifecycle_0","source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3372026-10-06T00:10:46.880Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:46.834696123Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"14f7e0de-a1f8-4c65-bbd8-08c960bc470a","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3382026-10-06T00:10:49.413Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:49.390298549Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
3392026-10-06T00:10:51.348Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.325139534Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3402026-10-06T00:10:51.348Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.325220156Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"14f7e0de-a1f8-4c65-bbd8-08c960bc470a","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","elapsed_milliseconds":4490,"source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3412026-10-06T00:10:51.372Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.327617901Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3422026-10-06T00:10:51.372Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.327832328Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3432026-10-06T00:10:51.372Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.327889536Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo 3 > /proc/sys/vm/drop_caches","timeout_duration":"Explicit(15s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3442026-10-06T00:10:51.372Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.329951154Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3452026-10-06T00:10:51.436Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.413488067Z","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","elapsed_milliseconds":85,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3462026-10-06T00:10:51.461Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.413770743Z","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","elapsed_milliseconds":10614,"vm":"migration_from_base","vm_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
3472026-10-06T00:10:51.461Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.413845815Z","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","elapsed_milliseconds":85,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3482026-10-06T00:10:51.461Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.414056905Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3492026-10-06T00:10:51.461Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.414128401Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3502026-10-06T00:10:51.485Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.451799948Z","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","elapsed_milliseconds":37,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3512026-10-06T00:10:51.485Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.452140182Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3522026-10-06T00:10:51.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-10-06T00:10:51.452259318Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3532026-10-06T00:10:51.509Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.462852046Z","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","elapsed_milliseconds":10,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3542026-10-06T00:10:51.509Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.462997552Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3552026-10-06T00:10:51.509Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.463060982Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3562026-10-06T00:10:51.533Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.495984269Z","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","elapsed_milliseconds":32,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3572026-10-06T00:10:51.533Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.496256175Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3582026-10-06T00:10:51.533Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.496320787Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3592026-10-06T00:10:51.533Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.507700226Z","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","elapsed_milliseconds":11,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3602026-10-06T00:10:51.533Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.507983203Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3612026-10-06T00:10:51.533Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.508100465Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3622026-10-06T00:10:51.563Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.540676393Z","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","elapsed_milliseconds":32,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3632026-10-06T00:10:51.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.540962175Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3642026-10-06T00:10:51.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.541064018Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"mount | grep ' / type tmpfs '","timeout_duration":"Explicit(15s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3652026-10-06T00:10:51.588Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.551428564Z","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","elapsed_milliseconds":10,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3662026-10-06T00:10:51.588Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.551580862Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3672026-10-06T00:10:51.588Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.551646817Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3682026-10-06T00:10:51.612Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.584624928Z","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","elapsed_milliseconds":32,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3692026-10-06T00:10:51.612Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.584875032Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3702026-10-06T00:10:51.612Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.584975813Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls /media/nvme0n1/boot","timeout_duration":"Explicit(15s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3712026-10-06T00:10:51.636Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.595475305Z","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","elapsed_milliseconds":10,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3722026-10-06T00:10:51.636Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.595704619Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3732026-10-06T00:10:51.636Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.59581029Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3742026-10-06T00:10:51.662Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.639813688Z","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","elapsed_milliseconds":44,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3752026-10-06T00:10:51.686Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.640074453Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3762026-10-06T00:10:51.686Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.640184121Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3772026-10-06T00:10:51.686Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.65072489Z","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","elapsed_milliseconds":10,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3782026-10-06T00:10:51.686Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.651038685Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3792026-10-06T00:10:51.686Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.651152471Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3802026-10-06T00:10:51.710Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.682967226Z","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","elapsed_milliseconds":31,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3812026-10-06T00:10:51.710Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.683228021Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3822026-10-06T00:10:51.710Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.683335154Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"! dmesg | grep -q 'reset controller'","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3832026-10-06T00:10:51.734Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.694650802Z","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","elapsed_milliseconds":11,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3842026-10-06T00:10:51.734Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.694904333Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3852026-10-06T00:10:51.734Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.695014071Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3862026-10-06T00:10:51.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.727795667Z","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","elapsed_milliseconds":32,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3872026-10-06T00:10:51.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.728106606Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3882026-10-06T00:10:51.758Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.728222736Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3892026-10-06T00:10:51.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.738705067Z","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","elapsed_milliseconds":10,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3902026-10-06T00:10:51.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.738977043Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3912026-10-06T00:10:51.782Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.739089977Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3922026-10-06T00:10:51.806Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.771799366Z","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","elapsed_milliseconds":32,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3932026-10-06T00:10:51.806Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.772016738Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3942026-10-06T00:10:51.806Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.772322117Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3952026-10-06T00:10:51.806Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.772380297Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
3962026-10-06T00:10:51.806Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.772480547Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3972026-10-06T00:10:51.806Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.77252407Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10441}
3982026-10-06T00:10:51.806Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:51.773900268Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
3992026-10-06T00:10:52.270Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.246539938Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
4002026-10-06T00:10:52.355Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.331840705Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
4012026-10-06T00:10:52.378Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.331978636Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-b4623d6d-99bf-4cc8-90d4-e10e44231145\"]","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
4022026-10-06T00:10:52.423Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.357833114Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
4032026-10-06T00:10:52.423Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.357899771Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-f6955288-dda9-4f08-a8bb-2535bd576f66\"]","verb":"destroy","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
4042026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.375450548Z","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","elapsed_milliseconds":603,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c"}
4052026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.375658352Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":6059,"vm":"migration_from_base_lifecycle_0","vm_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
4062026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.37572106Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":603}
4072026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.375754734Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"9b4e0b07-fd07-49b1-9c6f-315884b5019c","elapsed_milliseconds":6059,"source_id":"8958cad2-9f76-45ca-b2a9-a022e327bf62"}
4082026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.375835036Z","target":"phd_runner::execute","line":91,"file":"phd-tests/runner/src/execute.rs"}
4092026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.375832331Z","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":11691}
4102026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.375894028Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
4112026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.375948321Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4122026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.376114616Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4132026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.376225677Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4142026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.376296681Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4152026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.376370061Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4162026-10-06T00:10:52.424Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.376452126Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4172026-10-06T00:10:52.449Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.387920724Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 1.30G 25.3T 1.30G /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4182026-10-06T00:10:52.449Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.388017818Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-5a99ad08-9765-4dde-8fc3-f23610d1fb3d\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4192026-10-06T00:10:52.449Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.405982872Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-5a99ad08-9765-4dde-8fc3-f23610d1fb3d\", \"phd-artifacts/phd-clone-1c4c4b95-cd28-4cdd-8e98-2a81e45ae84c\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4202026-10-06T00:10:52.473Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.426853883Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-1c4c4b95-cd28-4cdd-8e98-2a81e45ae84c\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4212026-10-06T00:10:52.473Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.438314867Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-1c4c4b95-cd28-4cdd-8e98-2a81e45ae84c 0B 25.3T 1.30G /phd-artifacts/phd-clone-1c4c4b95-cd28-4cdd-8e98-2a81e45ae84c\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4222026-10-06T00:10:52.473Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.438972633Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4232026-10-06T00:10:52.473Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.439043708Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4242026-10-06T00:10:52.473Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.439114572Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/4bf8fc6099e34afbdcfdef6b4e86494863090e3d681d8eb37a4e182353d1c2dd/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4252026-10-06T00:10:52.473Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.439178433Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/4bf8fc6099e34afbdcfdef6b4e86494863090e3d681d8eb37a4e182353d1c2dd/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4262026-10-06T00:10:52.473Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.43926122Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4272026-10-06T00:10:52.508Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 937","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.485715825Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4282026-10-06T00:10:52.533Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.499984844Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":60,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4292026-10-06T00:10:52.533Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.500113718Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4302026-10-06T00:10:52.533Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:52.50085853Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4312026-10-06T00:10:53.194Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.17225084Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
4322026-10-06T00:10:53.240Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.173463559Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 83cce87f-e41a-4b3d-b92d-e9e33b4623e8, name: \"phd-vm-83cce87f-e41a-4b3d-b92d-e9e33b4623e8\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: c8b6148c-57fd-4e78-9e44-1d20465a17ff, project_id: 05227fdf-48a1-4783-bd4f-439aead1bbe0, sled_id: e929a60e-ed3b-485a-8201-389bd3a94d0a, sled_serial: \"e929a60e-ed3b-485a-8201-389bd3a94d0a\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Creating }","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4332026-10-06T00:10:53.240Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.173620877Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4342026-10-06T00:10:53.240Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.173678215Z","target":"phd_framework::test_vm","line":580,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4352026-10-06T00:10:53.240Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.174761158Z","target":"phd_framework::test_vm","line":575,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":1}
4362026-10-06T00:10:53.240Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.174844807Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4372026-10-06T00:10:53.240Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.174903518Z","target":"phd_framework::test_vm","line":839,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","timeout_duration":"300s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4382026-10-06T00:10:53.240Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.17496262Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4392026-10-06T00:10:53.240Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.17501033Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4402026-10-06T00:10:53.240Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:53.175060265Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4412026-10-06T00:10:57.805Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.782242638Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":4607}
4422026-10-06T00:10:57.805Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.782338469Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4432026-10-06T00:10:57.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.782575449Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4442026-10-06T00:10:57.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.782633248Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4452026-10-06T00:10:57.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.782688884Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4462026-10-06T00:10:57.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.80203855Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":19}
4472026-10-06T00:10:57.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.802196059Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4482026-10-06T00:10:57.830Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.802532977Z","target":"phd_framework::test_vm","line":847,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4492026-10-06T00:10:57.831Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.802589454Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4502026-10-06T00:10:57.831Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.802632807Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4512026-10-06T00:10:57.858Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.835679824Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":33}
4522026-10-06T00:10:57.858Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.83582549Z","target":"phd_framework::test_vm","line":887,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4532026-10-06T00:10:57.858Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.835909349Z","target":"phd_framework::test_vm","line":890,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4660,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4542026-10-06T00:10:57.882Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.836178008Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4552026-10-06T00:10:57.882Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.836287877Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4562026-10-06T00:10:57.882Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.846942342Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":10}
4572026-10-06T00:10:57.882Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.847181716Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4582026-10-06T00:10:57.882Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.847286614Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4592026-10-06T00:10:57.906Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.880371223Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":33}
4602026-10-06T00:10:57.906Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.880690929Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4612026-10-06T00:10:57.906Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.880804955Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4622026-10-06T00:10:57.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.89116368Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":10}
4632026-10-06T00:10:57.930Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.891405438Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4642026-10-06T00:10:57.930Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.89149619Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4652026-10-06T00:10:57.953Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.924228421Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":32}
4662026-10-06T00:10:57.953Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.924485398Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4672026-10-06T00:10:57.953Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.924550221Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4682026-10-06T00:10:57.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.935225223Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":10}
4692026-10-06T00:10:57.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.93553488Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4702026-10-06T00:10:57.977Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.93561371Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4712026-10-06T00:10:58.001Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.967883676Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":32}
4722026-10-06T00:10:58.001Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.968174638Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4732026-10-06T00:10:58.001Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.968283815Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo $?","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4742026-10-06T00:10:58.025Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.978822368Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":10}
4752026-10-06T00:10:58.025Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.979062373Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4762026-10-06T00:10:58.025Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:57.979165949Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4772026-10-06T00:10:58.049Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.012293561Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":33}
4782026-10-06T00:10:58.049Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.012609319Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4792026-10-06T00:10:58.049Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.012723736Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4802026-10-06T00:10:58.049Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.023136221Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":10}
4812026-10-06T00:10:58.049Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.023378761Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4822026-10-06T00:10:58.049Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.023482938Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4832026-10-06T00:10:58.078Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.055710381Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":32}
4842026-10-06T00:10:58.102Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.056095487Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4852026-10-06T00:10:58.102Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.056201926Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo $?","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4862026-10-06T00:10:58.102Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.066870977Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":10}
4872026-10-06T00:10:58.102Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.067116702Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4882026-10-06T00:10:58.102Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.06722094Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4892026-10-06T00:10:58.126Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.100672655Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":33}
4902026-10-06T00:10:58.126Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.100879687Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4912026-10-06T00:10:58.126Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.101006067Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4922026-10-06T00:10:58.126Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.101056873Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4932026-10-06T00:10:58.126Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.101124Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4942026-10-06T00:10:58.126Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.101187781Z","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"}
4952026-10-06T00:10:58.126Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.10128207Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4962026-10-06T00:10:58.168Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 938","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.14545732Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4972026-10-06T00:10:58.191Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.158621322Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":57,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
4982026-10-06T00:10:58.191Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.15870471Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0"}
4992026-10-06T00:10:58.191Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.158769473Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"69003d2d-9b40-43ee-bbf9-6191edf42842","timeout_duration":"45s","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0"}
5002026-10-06T00:10:58.191Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.158833545Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c"}
5012026-10-06T00:10:58.192Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.159385922Z","target":"phd_framework::test_vm","line":455,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c"}
5022026-10-06T00:10:59.017Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.994164344Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 09f415e7-31bc-4241-8e94-119a39e5c09c, name: \"phd-vm-09f415e7-31bc-4241-8e94-119a39e5c09c\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: c8b6148c-57fd-4e78-9e44-1d20465a17ff, project_id: 05227fdf-48a1-4783-bd4f-439aead1bbe0, sled_id: 7a86bfd0-0040-4505-aacf-4391fbeb28cb, sled_serial: \"7a86bfd0-0040-4505-aacf-4391fbeb28cb\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c"}
5032026-10-06T00:10:59.017Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:10:58.994382478Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0","migration_id":"69003d2d-9b40-43ee-bbf9-6191edf42842"}
5042026-10-06T00:11:01.570Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:01.547240629Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7847}}"}
5052026-10-06T00:11:02.515Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.492914946Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0"}
5062026-10-06T00:11:02.516Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.492976343Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0","migration_id":"69003d2d-9b40-43ee-bbf9-6191edf42842","elapsed_milliseconds":3498}
5072026-10-06T00:11:02.539Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.495696799Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5082026-10-06T00:11:02.540Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.496113677Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5092026-10-06T00:11:02.540Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.496221685Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5102026-10-06T00:11:02.540Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.49798271Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5112026-10-06T00:11:02.602Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.579248944Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":83}
5122026-10-06T00:11:02.627Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.57946318Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","elapsed_milliseconds":10079}
5132026-10-06T00:11:02.627Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.579613344Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","elapsed_milliseconds":83}
5142026-10-06T00:11:02.627Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.579843851Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5152026-10-06T00:11:02.627Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.579916148Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5162026-10-06T00:11:02.651Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.60714519Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","elapsed_milliseconds":27}
5172026-10-06T00:11:02.651Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.607313529Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__BASE_PROPOLIS","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5182026-10-06T00:11:02.651Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.60745105Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5192026-10-06T00:11:02.651Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.607540169Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\", metrics: None }","vm_name":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5202026-10-06T00:11:02.651Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.607653804Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/4bf8fc6099e34afbdcfdef6b4e86494863090e3d681d8eb37a4e182353d1c2dd/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5212026-10-06T00:11:02.651Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.607716423Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/4bf8fc6099e34afbdcfdef6b4e86494863090e3d681d8eb37a4e182353d1c2dd/propolis-server\"","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5222026-10-06T00:11:02.651Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.607799019Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5232026-10-06T00:11:02.677Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 940","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.653975934Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5242026-10-06T00:11:02.700Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.667307672Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":59,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5252026-10-06T00:11:02.700Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.667395929Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1"}
5262026-10-06T00:11:02.700Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.667467485Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"24885384-3f6c-4f16-9e86-938449aa77a1","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1"}
5272026-10-06T00:11:02.700Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.667535785Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421"}
5282026-10-06T00:11:02.700Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:02.66808199Z","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)","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421"}
5292026-10-06T00:11:03.274Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:03.251115311Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 5dc3d82c-ff27-486c-8d07-9b986fbba421, name: \"phd-vm-5dc3d82c-ff27-486c-8d07-9b986fbba421\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: c8b6148c-57fd-4e78-9e44-1d20465a17ff, project_id: 05227fdf-48a1-4783-bd4f-439aead1bbe0, sled_id: 31dc86a0-9c92-4b87-8572-04e9513e4321, sled_serial: \"31dc86a0-9c92-4b87-8572-04e9513e4321\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421"}
5302026-10-06T00:11:03.298Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:03.251295884Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1","migration_id":"24885384-3f6c-4f16-9e86-938449aa77a1"}
5312026-10-06T00:11:05.815Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:05.79178453Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7894}}"}
5322026-10-06T00:11:06.844Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:06.819866132Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1"}
5332026-10-06T00:11:06.844Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:06.819947065Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1","migration_id":"24885384-3f6c-4f16-9e86-938449aa77a1","elapsed_milliseconds":3568}
5342026-10-06T00:11:06.868Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:06.823019289Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5352026-10-06T00:11:06.868Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:06.823286595Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5362026-10-06T00:11:06.868Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:06.823353201Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5372026-10-06T00:11:06.868Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:06.82489845Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5382026-10-06T00:11:06.933Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:06.909908169Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","elapsed_milliseconds":86}
5392026-10-06T00:11:06.956Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:06.910144778Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":8751,"target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"09f415e7-31bc-4241-8e94-119a39e5c09c"}
5402026-10-06T00:11:06.956Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:06.910272911Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","source_id":"83cce87f-e41a-4b3d-b92d-e9e33b4623e8","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":8751}
5412026-10-06T00:11:07.960Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.936916549Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","elapsed_milliseconds":1113}
5422026-10-06T00:11:07.984Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.937198915Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5432026-10-06T00:11:07.984Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.937308392Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5442026-10-06T00:11:08.008Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.970894952Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","elapsed_milliseconds":33}
5452026-10-06T00:11:08.008Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.971035449Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5462026-10-06T00:11:08.008Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.971138835Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5472026-10-06T00:11:08.008Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.971197806Z","target":"phd_framework::test_vm","line":318,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_2","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\", metrics: None }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5482026-10-06T00:11:08.008Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.971275764Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5492026-10-06T00:11:08.008Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.971339365Z","target":"phd_framework::test_vm::server","line":66,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9006","bootrom_path":"\"/phd-artifacts/740187046a7267d0de72d3455070333547dbc0ea023531471fb2b2a61effa448/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5502026-10-06T00:11:08.008Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:07.971423985Z","target":"phd_framework::log_config","line":84,"file":"phd-tests/framework/src/log_config.rs","stdout_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5512026-10-06T00:11:08.040Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 942","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:08.017523262Z","target":"phd_framework::test_vm::server","line":127,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5522026-10-06T00:11:08.064Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:08.031358146Z","target":"phd_framework::test_vm","line":300,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":60,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5532026-10-06T00:11:08.064Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:08.031457574Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2"}
5542026-10-06T00:11:08.064Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:08.031537225Z","target":"phd_framework::test_vm","line":642,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"eb79e425-ddd0-4e4d-b251-6258dcd21a1d","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2"}
5552026-10-06T00:11:08.064Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:08.031615373Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45"}
5562026-10-06T00:11:08.064Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:08.032211433Z","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)","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45"}
5572026-10-06T00:11:08.778Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:08.755209125Z","target":"phd_framework::test_vm","line":514,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { id: 0d8bc8f8-6712-497f-8d9b-676f55fa8a45, name: \"phd-vm-0d8bc8f8-6712-497f-8d9b-676f55fa8a45\", description: \"Pheidippides-managed VM\", metadata: InstanceMetadata { silo_id: c8b6148c-57fd-4e78-9e44-1d20465a17ff, project_id: 05227fdf-48a1-4783-bd4f-439aead1bbe0, sled_id: c9a9f71b-a48f-4ef5-8b30-7945e2d213d9, sled_serial: \"c9a9f71b-a48f-4ef5-8b30-7945e2d213d9\", sled_revision: 1, sled_model: \"pheidippes\" } }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45"}
5582026-10-06T00:11:08.778Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:08.755427028Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2","migration_id":"eb79e425-ddd0-4e4d-b251-6258dcd21a1d"}
5592026-10-06T00:11:11.324Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:11.300965614Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7941}}"}
5602026-10-06T00:11:13.431Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.407186161Z","target":"phd_framework::test_vm","line":676,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2"}
5612026-10-06T00:11:13.431Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.407284367Z","target":"phd_framework::test_vm","line":663,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2","migration_id":"eb79e425-ddd0-4e4d-b251-6258dcd21a1d","elapsed_milliseconds":4651}
5622026-10-06T00:11:13.455Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.410458013Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5632026-10-06T00:11:13.455Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.410762199Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5642026-10-06T00:11:13.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-10-06T00:11:13.410826241Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5652026-10-06T00:11:13.455Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.412846821Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5662026-10-06T00:11:13.514Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.490535403Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","elapsed_milliseconds":79}
5672026-10-06T00:11:13.537Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.490870258Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","elapsed_milliseconds":80}
5682026-10-06T00:11:13.538Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.490936684Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10823,"target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421"}
5692026-10-06T00:11:13.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.491111134Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5702026-10-06T00:11:13.538Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.491086037Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","source_id":"09f415e7-31bc-4241-8e94-119a39e5c09c","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":10823}
5712026-10-06T00:11:13.538Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.491199702Z","target":"phd_framework::test_vm","line":920,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5722026-10-06T00:11:13.561Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.521462642Z","target":"phd_framework::test_vm","line":913,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","elapsed_milliseconds":30}
5732026-10-06T00:11:13.561Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.521631162Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5742026-10-06T00:11:13.561Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.521847031Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
5752026-10-06T00:11:13.561Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.521955286Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":20349}
5762026-10-06T00:11:13.561Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.522001424Z","target":"phd_runner::execute","line":141,"file":"phd-tests/runner/src/execute.rs"}
5772026-10-06T00:11:13.562Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.522106002Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5782026-10-06T00:11:13.562Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:13.523627285Z","target":"phd_framework::test_vm","line":1195,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5792026-10-06T00:11:14.292Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.268357601Z","target":"phd_framework::test_vm::server","line":177,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5802026-10-06T00:11:14.382Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.359230832Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5812026-10-06T00:11:14.382Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.359365778Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-1c4c4b95-cd28-4cdd-8e98-2a81e45ae84c\"]","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5822026-10-06T00:11:14.411Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.387507369Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5832026-10-06T00:11:14.411Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.387572603Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-5a99ad08-9765-4dde-8fc3-f23610d1fb3d\"]","verb":"destroy","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5842026-10-06T00:11:14.434Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.406742857Z","target":"phd_framework::test_vm","line":1172,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","elapsed_milliseconds":884}
5852026-10-06T00:11:14.434Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.406979075Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":884}
5862026-10-06T00:11:14.434Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.406982562Z","target":"phd_framework::test_vm","line":412,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":6375,"target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45"}
5872026-10-06T00:11:14.434Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.407090015Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5882026-10-06T00:11:14.434Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.407086158Z","target":"phd_framework::test_vm","line":609,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target_id":"0d8bc8f8-6712-497f-8d9b-676f55fa8a45","source_id":"5dc3d82c-ff27-486c-8d07-9b986fbba421","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":6375}
5892026-10-06T00:11:14.434Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.407136123Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5902026-10-06T00:11:14.434Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.407141302Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":22030,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
5912026-10-06T00:11:14.434Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 93.06s
5922026-10-06T00:11:14.434Z
5932026-10-06T00:11:14.435Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"BRM42220010","pid":912,"time":"2026-10-06T00:11:14.408880128Z","target":"phd_runner","line":41,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5942026-10-06T00:11:14.558Z
5952026-10-06T00:11:14.558Zreal 1:34.362043710
5962026-10-06T00:11:14.558Zuser 51.353809436
5972026-10-06T00:11:14.581Zsys 21.893982360
5982026-10-06T00:11:14.581Ztrap 0.007592655
5992026-10-06T00:11:14.581Ztflt 0.006329703
6002026-10-06T00:11:14.581Zdflt 0.001808005
6012026-10-06T00:11:14.581Zkflt 0.000000000
6022026-10-06T00:11:14.581Zlock 3:40:18.246087097
6032026-10-06T00:11:14.581Zslp 4:27.875455234
6042026-10-06T00:11:14.581Zlat 2.349920689
6052026-10-06T00:11:14.581Zstop 54.439560284
6062026-10-06T00:11:14.581Z+ failcount=0
6072026-10-06T00:11:14.581Z+ set -e
6082026-10-06T00:11:14.581Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd .
6092026-10-06T00:11:14.605ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
6102026-10-06T00:11:14.605Za ./ 0K
6112026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::serial_history/ 0K
6122026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stdout.log 159K
6132026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.stderr.log 0K
6142026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base.serial.log 7K
6152026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stdout.log 165K
6162026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::serial_history/migration_serial_history_base_lifecycle_0.stderr.log 0K
6172026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::can_migrate_from_base/ 0K
6182026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stdout.log 158K
6192026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.stderr.log 0K
6202026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base.serial.log 7K
6212026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stdout.log 165K
6222026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::can_migrate_from_base/migration_from_base_lifecycle_0.stderr.log 0K
6232026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/ 0K
6242026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stdout.log 157K
6252026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.stderr.log 0K
6262026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back.serial.log 7K
6272026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stdout.log 268K
6282026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_0.stderr.log 0K
6292026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stdout.log 268K
6302026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_1.stderr.log 0K
6312026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stdout.log 164K
6322026-10-06T00:11:14.606Za ./phd_tests::migrate::from_base::migration_from_base_and_back/migration_from_base_and_back_lifecycle_2.stderr.log 0K
6332026-10-06T00:11:14.606Z+ exitcode=0
6342026-10-06T00:11:14.606Z+ '[' 0 -eq 0 ']'
6352026-10-06T00:11:14.606Z+ echo
6362026-10-06T00:11:14.606Z+ echo 'ALL TESTS PASSED'
6372026-10-06T00:11:14.606Z
6382026-10-06T00:11:14.606ZALL TESTS PASSED
6392026-10-06T00:11:14.606Z+ echo
6402026-10-06T00:11:14.606Z
6412026-10-06T00:11:14.606Z+ find /dev/vmm -mindepth 1 -maxdepth 1
6422026-10-06T00:11:14.606Z+ read
6432026-10-06T00:11:14.606Z+ exit 0
6442026-10-06T00:11:14.606Zprocess exited: duration 165615 ms, exit code 0
 
6452026-10-06T00:11:14.656Zfound 2 output files
6462026-10-06T00:11:14.656Zuploading: /tmp/phd-runner.log (202742 bytes)
6472026-10-06T00:11:16.253Zuploaded: /tmp/phd-runner.log
6482026-10-06T00:11:16.253Zuploading: /tmp/phd-tmp-files.tar.gz (133618 bytes)
6492026-10-06T00:11:17.678Zuploaded: /tmp/phd-tmp-files.tar.gz