01JP14C9525MV7QRY7GZZABS50: 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-opte",
    ),
    access_repos: [],
    publish: [],
    skip_clone: true,
}

Buildomat Job: 01JP14CHXHZE1GZYYKZG4WEBNB

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-03-10T23:04:02.332Zjob dependencies complete; ready to run (waiting for 7 m 23 s)
22025-03-10T23:08:23.765Zjob assigned to worker 01JP14T8HQG81SX55VVD0J7VR8 [factory lab, sock/12019] (queued for 4 m 21 s)
32025-03-10T23:08:23.852Zhttp://172.20.0.5:9969/ipxe/sock... ok
42025-03-10T23:08:23.894Zhttp://172.20.0.5:9969/os/sock/platform/i86pc/kernel/amd64/unix... ok
52025-03-10T23:08:23.928Zhttp://172.20.0.5:9969/os/sock/platform/i86pc/amd64/boot_archive... ok
62025-03-10T23:08:23.961Zhttp://172.20.0.5:9969/os/sock/platform/i86pc/amd64/boot_archive.hash... ok
72025-03-10T23:08:23.995Zhttp://172.20.0.5:9969/postboot/sock... ok
82025-03-10T23:08:24.028ZwcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U
92025-03-10T23:08:24.062Zcpu0: microcode has been updated from version 0xa001133 to 0xa0011d5
102025-03-10T23:08:24.095ZOxide Helios Version helios-2.0.23032 64-bit
112025-03-10T23:08:24.129ZConfiguring devices.
122025-03-10T23:08:24.162Z##################################################
132025-03-10T23:08:24.196Z#### ############# ##
142025-03-10T23:08:24.229Z### ### ############ ##
152025-03-10T23:08:24.263Z## ### # ## ### ## Oxide Computer Company ##
162025-03-10T23:08:24.296Z## ## ## ### # ### ##
172025-03-10T23:08:24.330Z## # ### #### #### This Station Under ##
182025-03-10T23:08:24.363Z### ### #### # ### Computer Control ##
192025-03-10T23:08:24.397Z#### #### ### ## ##
202025-03-10T23:08:24.430Z##################################################
212025-03-10T23:08:24.463ZHostname: sock
222025-03-10T23:08:24.497ZLoading smf(7) service descriptions:
232025-03-10T23:08:24.643Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
242025-03-10T23:08:24.667Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
252025-03-10T23:08:24.667Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
262025-03-10T23:08:24.693Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
272025-03-10T23:08:24.693Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
282025-03-10T23:08:37.134Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
292025-03-10T23:08:37.134Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
302025-03-10T23:08:37.192Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
312025-03-10T23:08:37.217Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
322025-03-10T23:09:01.449Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
332025-03-10T23:09:01.474Zstarting task 0: "setup"
342025-03-10T23:09:01.474Z++ uname -s
352025-03-10T23:09:01.474Z+ kern=SunOS
362025-03-10T23:09:01.474Z+ build_user=build
372025-03-10T23:09:01.474Z+ build_uid=12345
382025-03-10T23:09:01.474Z+ work_dir=/work
392025-03-10T23:09:01.474Z+ input_dir=/input
402025-03-10T23:09:01.474Z+ [[ 0 == 12345 ]]
412025-03-10T23:09:01.474Z+ case "$kern" in
422025-03-10T23:09:01.474Z+ groupadd -g 12345 build
432025-03-10T23:09:01.474Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
442025-03-10T23:09:03.467Z+ zfs create -o mountpoint=/work rpool/work
452025-03-10T23:09:03.492Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
462025-03-10T23:09:03.492Z+ home_fs=zfs
472025-03-10T23:09:03.492Z+ [[ zfs == autofs ]]
482025-03-10T23:09:03.492Z+ mkdir -p /home/build
492025-03-10T23:09:03.492Z+ chown build:build /home/build /work
502025-03-10T23:09:05.492Z+ chmod 0700 /home/build /work
512025-03-10T23:09:05.516Zprocess exited: duration 4046 ms, exit code 0
 
522025-03-10T23:09:05.564Zstarting task 1: "authentication"
532025-03-10T23:09:05.609Zprocess exited: duration 44 ms, exit code 0
 
542025-03-10T23:09:05.657Zstarting task 2: "build"
552025-03-10T23:09:05.681Z+ indir=/input
562025-03-10T23:09:05.681Z+ indir_suffix='phd-build/out/*.tar.gz'
572025-03-10T23:09:05.681Z+ phddir=/work/phd-test
582025-03-10T23:09:05.681Z+ pfexec zpool create -f phd-artifacts c1t1d0 c2t1d0
592025-03-10T23:09:05.806Z+ artifactdir=/phd-artifacts
602025-03-10T23:09:05.806Z+ banner Inputs
612025-03-10T23:09:05.831Z ###
622025-03-10T23:09:05.831Z # # # ##### # # ##### ####
632025-03-10T23:09:05.831Z # ## # # # # # # #
642025-03-10T23:09:05.831Z # # # # # # # # # ####
652025-03-10T23:09:05.831Z # # # # ##### # # # #
662025-03-10T23:09:05.831Z # # ## # # # # # #
672025-03-10T23:09:05.831Z ### # # # #### # ####
682025-03-10T23:09:05.831Z
692025-03-10T23:09:05.831Z+ find /input -ls
702025-03-10T23:09:05.831Z 34 1 drwxr-xr-x 3 root root 3 Mar 10 23:08 /input
712025-03-10T23:09:05.831Z 2 1 drwxr-xr-x 3 root root 3 Mar 10 23:08 /input/phd-build
722025-03-10T23:09:05.831Z 3 2 drwxr-xr-x 2 root root 7 Mar 10 23:08 /input/phd-build/out
732025-03-10T23:09:05.831Z 129 1 -rw-r--r-- 1 root root 65 Mar 10 23:08 /input/phd-build/out/phd-runner.sha256.txt
742025-03-10T23:09:05.831Z 128 3 -rw-r--r-- 1 root root 2402 Mar 10 23:08 /input/phd-build/out/phd-run-with-args.sh
752025-03-10T23:09:05.831Z 257 136867 -rw-r--r-- 1 root root 140060299 Mar 10 23:09 /input/phd-build/out/propolis-server-debug.tar.gz
762025-03-10T23:09:05.831Z 256 1 -rw-r--r-- 1 root root 65 Mar 10 23:08 /input/phd-build/out/propolis-server-debug.sha256.txt
772025-03-10T23:09:05.831Z 130 69529 -rw-r--r-- 1 root root 71152228 Mar 10 23:08 /input/phd-build/out/phd-runner.tar.gz
782025-03-10T23:09:05.831Z+ rm -rf /work/phd-test
792025-03-10T23:09:05.831Z+ mkdir /work/phd-test
802025-03-10T23:09:05.831Z+ for p in $indir/$indir_suffix
812025-03-10T23:09:05.831Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
822025-03-10T23:09:07.381ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
832025-03-10T23:09:07.382Zx phd-runner, 252540880 bytes, 493244 tape blocks
842025-03-10T23:09:07.382Zx artifacts.toml, 548 bytes, 2 tape blocks
852025-03-10T23:09:07.406Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
862025-03-10T23:09:08.882Z+ for f in $(tar tf "$p")
872025-03-10T23:09:08.882Z+ chmod +x /work/phd-test/phd-runner
882025-03-10T23:09:08.907Z+ for f in $(tar tf "$p")
892025-03-10T23:09:08.907Z+ chmod +x /work/phd-test/artifacts.toml
902025-03-10T23:09:08.907Z+ for p in $indir/$indir_suffix
912025-03-10T23:09:08.907Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
922025-03-10T23:09:12.097ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
932025-03-10T23:09:12.097Zx propolis-server, 528251712 bytes, 1031742 tape blocks
942025-03-10T23:09:12.122Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
952025-03-10T23:09:15.014Z+ for f in $(tar tf "$p")
962025-03-10T23:09:15.015Z+ chmod +x /work/phd-test/propolis-server
972025-03-10T23:09:15.039Z+ ls /work/phd-test
982025-03-10T23:09:15.039Zartifacts.toml
992025-03-10T23:09:15.040Zphd-runner
1002025-03-10T23:09:15.040Zpropolis-server
1012025-03-10T23:09:15.040Z+ banner Setup
1022025-03-10T23:09:15.040Z #####
1032025-03-10T23:09:15.040Z# # ###### ##### # # #####
1042025-03-10T23:09:15.040Z# # # # # # #
1052025-03-10T23:09:15.040Z ##### ##### # # # # #
1062025-03-10T23:09:15.040Z # # # # # #####
1072025-03-10T23:09:15.040Z# # # # # # #
1082025-03-10T23:09:15.040Z ##### ###### # #### #
1092025-03-10T23:09:15.040Z
1102025-03-10T23:09:15.040Z+ tmpdir=/tmp/propolis-phd
1112025-03-10T23:09:15.040Z+ '[' '!' -d /tmp/propolis-phd ']'
1122025-03-10T23:09:15.040Z+ mkdir /tmp/propolis-phd
1132025-03-10T23:09:15.040Z+ pfexec /usr/lib/rsrvrctl -s 4096
1142025-03-10T23:09:15.755Z+ banner Tests
1152025-03-10T23:09:15.780Z#######
1162025-03-10T23:09:15.780Z # ###### #### ##### ####
1172025-03-10T23:09:15.780Z # # # # #
1182025-03-10T23:09:15.780Z # ##### #### # ####
1192025-03-10T23:09:15.780Z # # # # #
1202025-03-10T23:09:15.780Z # # # # # # #
1212025-03-10T23:09:15.780Z # ###### #### # ####
1222025-03-10T23:09:15.780Z
1232025-03-10T23:09:15.780Z+ runner=/work/phd-test/phd-runner
1242025-03-10T23:09:15.780Z+ artifacts=/work/phd-test/artifacts.toml
1252025-03-10T23:09:15.780Z+ propolis=/work/phd-test/propolis-server
1262025-03-10T23:09:15.780Z+ ls /work/phd-test/phd-runner
1272025-03-10T23:09:15.780Z/work/phd-test/phd-runner
1282025-03-10T23:09:15.780Z+ ls /work/phd-test/artifacts.toml
1292025-03-10T23:09:15.780Z/work/phd-test/artifacts.toml
1302025-03-10T23:09:15.780Z+ ls /work/phd-test/propolis-server
1312025-03-10T23:09:15.780Z/work/phd-test/propolis-server
1322025-03-10T23:09:15.780Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1332025-03-10T23:09:15.780Z+ set +e
1342025-03-10T23:09:15.780Z+ RUST_BACKTRACE=1
1352025-03-10T23:09:15.780Z+ RUST_LOG=info,phd=debug
1362025-03-10T23:09:15.780Z+ 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
1372025-03-10T23:09:15.780Z+ tee /tmp/phd-runner.log
1382025-03-10T23:09:15.805Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:15.596754762Z","target":"phd_runner","line":35,"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\"), server_logging_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 }), disable_ansi: false, emit_bunyan: true }"}
1392025-03-10T23:09:15.805Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:15.599197228Z","target":"phd_framework::artifacts::store","line":221,"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(\"6d92acf0a22718dd4175d7c64dbcf7aaec3740bd\"), sha256: \"29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f\" }), 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: 2305, tv_nsec: 22890648 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1402025-03-10T23:09:15.805Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:15.59925102Z","target":"phd_framework::artifacts::store","line":229,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1412025-03-10T23:09:15.805Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:15.599351151Z","target":"phd_framework::artifacts::store","line":313,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"d2d8f8ad449df7e2befb7ee2723a442dd74b9b72"}
1422025-03-10T23:09:15.805Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:15.599479704Z","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/crucible/nightly-image/d2d8f8ad449df7e2befb7ee2723a442dd74b9b72/crucible-nightly.sha256.txt"}
1432025-03-10T23:09:15.941Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:15.74228079Z","target":"phd_framework::artifacts::store","line":250,"file":"phd-tests/framework/src/artifacts/store.rs"}
1442025-03-10T23:09:16.366Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.167647268Z","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/9ee2e1f5f8d7cc3543b6985af36c0df7f81498c5/propolis-server.sha256.txt"}
1452025-03-10T23:09:16.470Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.27201985Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1462025-03-10T23:09:16.495Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.272110752Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1472025-03-10T23:09:16.495Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.272237174Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1482025-03-10T23:09:16.495Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.272299416Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1492025-03-10T23:09:16.495Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.272337676Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1502025-03-10T23:09:16.495Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.272373967Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1512025-03-10T23:09:16.495Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.2725536Z","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"}
1522025-03-10T23:09:16.495Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.272978128Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1532025-03-10T23:09:16.495Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.273186952Z","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/6d92acf0a22718dd4175d7c64dbcf7aaec3740bd/OVMF_CODE.fd","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1542025-03-10T23:09:17.057Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.858148178Z","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::migration_from_base_and_back"}
1552025-03-10T23:09:17.081Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:16.858339341Z","target":"phd_framework::artifacts::store","line":621,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1562025-03-10T23:09:51.229Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.030690639Z","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"}
1572025-03-10T23:09:51.253Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.030791041Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1582025-03-10T23:09:51.278Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.05586631Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2M 1.80T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1592025-03-10T23:09:51.278Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.056310868Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-4ff0d69b-8e0d-47df-bfcd-4b28b7590ca5\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1602025-03-10T23:09:51.309Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.111114184Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-4ff0d69b-8e0d-47df-bfcd-4b28b7590ca5\", \"phd-artifacts/phd-clone-28318da7-b1bd-4847-ba88-9fa5c098f3fb\"]","verb":"clone","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1612025-03-10T23:09:51.334Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.13290832Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-28318da7-b1bd-4847-ba88-9fa5c098f3fb\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1622025-03-10T23:09:51.358Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.14439865Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-28318da7-b1bd-4847-ba88-9fa5c098f3fb 0B 1.80T 48.9M /phd-artifacts/phd-clone-28318da7-b1bd-4847-ba88-9fa5c098f3fb\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1632025-03-10T23:09:51.358Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.145189345Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1642025-03-10T23:09:51.358Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.145240416Z","target":"phd_framework::test_vm","line":211,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1652025-03-10T23:09:51.358Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.145297217Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/699c2d2c5e97e63733ab85fce044388baefe882761373e5c02190990dd286770/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1662025-03-10T23:09:51.358Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:09:51.145353538Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/9ee2e1f5f8d7cc3543b6985af36c0df7f81498c5/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1672025-03-10T23:10:16.443Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:16.242736651Z","target":"phd_framework::artifacts::store","line":162,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/699c2d2c5e97e63733ab85fce044388baefe882761373e5c02190990dd286770/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1682025-03-10T23:10:16.443Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:16.242829583Z","target":"phd_framework::artifacts::store","line":521,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1692025-03-10T23:10:29.434Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.235466344Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/699c2d2c5e97e63733ab85fce044388baefe882761373e5c02190990dd286770/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1702025-03-10T23:10:29.434Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.235567986Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1712025-03-10T23:10:29.484Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 868","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.285692033Z","target":"phd_framework::test_vm::server","line":107,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1722025-03-10T23:10:29.511Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.28610837Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":38140,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1732025-03-10T23:10:29.511Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.286391106Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1742025-03-10T23:10:29.512Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.287287113Z","target":"phd_framework::test_vm","line":320,"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","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1752025-03-10T23:10:29.977Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.778635711Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1762025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.780027358Z","target":"phd_framework::test_vm","line":379,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65, metadata: InstanceMetadata { project_id: 15ba45b8-4f53-4512-950f-e62eb49080da, silo_id: f1211c9e-be87-4d22-acc5-5eda13de6d8a, sled_id: 6e9c2fd6-6d7b-4eea-a308-0434a685251e, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"6e9c2fd6-6d7b-4eea-a308-0434a685251e\" }, name: \"phd-vm-9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65\" }, state: Creating }","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1772025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.780184241Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":493,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1782025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.780316154Z","target":"phd_framework::test_vm","line":440,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1792025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.780387275Z","target":"phd_framework::test_vm","line":445,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1802025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.78119333Z","target":"phd_framework::test_vm","line":440,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1812025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.781283442Z","target":"phd_framework::test_vm","line":757,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1822025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.781330323Z","target":"phd_framework::test_vm","line":706,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","timeout_duration":"300s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1832025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.781366683Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1842025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.781400814Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1852025-03-10T23:10:30.002Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:29.781450685Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1862025-03-10T23:10:34.267Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.068047083Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4286,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1872025-03-10T23:10:34.267Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.068127565Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1882025-03-10T23:10:34.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.068472201Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1892025-03-10T23:10:34.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.068522972Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1902025-03-10T23:10:34.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.068559033Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1912025-03-10T23:10:34.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.086420484Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":17,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1922025-03-10T23:10:34.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.086508415Z","target":"phd_framework::test_vm","line":714,"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"}
1932025-03-10T23:10:34.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.086711039Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1942025-03-10T23:10:34.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.08677204Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1952025-03-10T23:10:34.291Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.086820821Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1962025-03-10T23:10:34.318Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.119658998Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
1972025-03-10T23:10:34.343Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.11976032Z","target":"phd_framework::test_vm","line":754,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1982025-03-10T23:10:34.343Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.119826531Z","target":"phd_framework::test_vm","line":757,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4338,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1992025-03-10T23:10:34.343Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.119967694Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2002025-03-10T23:10:34.343Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.120023825Z","target":"phd_framework::test_vm","line":779,"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","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2012025-03-10T23:10:34.343Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.131410323Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2022025-03-10T23:10:34.343Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.131650927Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2032025-03-10T23:10:34.343Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.131732339Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2042025-03-10T23:10:34.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.153343511Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":21,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2052025-03-10T23:10:34.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.153531045Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2062025-03-10T23:10:34.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.153589606Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2072025-03-10T23:10:34.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.164007185Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2082025-03-10T23:10:34.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.16425289Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2092025-03-10T23:10:34.367Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.164332941Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2102025-03-10T23:10:34.396Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.197248039Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2112025-03-10T23:10:34.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.197396622Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2122025-03-10T23:10:34.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.197447853Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2132025-03-10T23:10:34.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.20773552Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2142025-03-10T23:10:34.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.207866672Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2152025-03-10T23:10:34.420Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.207915383Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2162025-03-10T23:10:34.445Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.230503464Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2172025-03-10T23:10:34.445Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.230697038Z","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"}
2182025-03-10T23:10:34.445Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.23079595Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2192025-03-10T23:10:34.445Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.230863231Z","target":"phd_framework::test_vm","line":211,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2202025-03-10T23:10:34.445Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.230968333Z","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::migration_from_base_and_back"}
2212025-03-10T23:10:34.445Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.231019774Z","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::migration_from_base_and_back"}
2222025-03-10T23:10:34.445Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.231059685Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2232025-03-10T23:10:34.445Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.231097065Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2242025-03-10T23:10:34.469Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 869","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.247762564Z","target":"phd_framework::test_vm::server","line":107,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2252025-03-10T23:10:34.469Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.247964947Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":17,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2262025-03-10T23:10:34.469Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.248060519Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","source":"migration_from_base_and_back","target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2272025-03-10T23:10:34.469Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.24812343Z","target":"phd_framework::test_vm","line":507,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"7b1591da-2b1e-4fff-899b-fd6e6c36d903","timeout_duration":"45s","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","source":"migration_from_base_and_back","target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2282025-03-10T23:10:34.469Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.248189222Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2292025-03-10T23:10:34.469Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.248723462Z","target":"phd_framework::test_vm","line":320,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2302025-03-10T23:10:34.986Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.787370003Z","target":"phd_framework::test_vm","line":379,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: c5af77a0-13e2-4664-a9c1-7a757bc3c83b, metadata: InstanceMetadata { project_id: 15ba45b8-4f53-4512-950f-e62eb49080da, silo_id: f1211c9e-be87-4d22-acc5-5eda13de6d8a, sled_id: c95f1ca2-5aa6-4356-afa9-b6c09ee0d8f8, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"c95f1ca2-5aa6-4356-afa9-b6c09ee0d8f8\" }, name: \"phd-vm-c5af77a0-13e2-4664-a9c1-7a757bc3c83b\" }, state: Migrating }","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2312025-03-10T23:10:35.010Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.787483875Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","elapsed_milliseconds":539,"vm":"migration_from_base_and_back_lifecycle_0"}
2322025-03-10T23:10:35.010Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:34.787541736Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","migration_id":"7b1591da-2b1e-4fff-899b-fd6e6c36d903","source":"migration_from_base_and_back","target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2332025-03-10T23:10:37.449Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:37.250405135Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7760}}"}
2342025-03-10T23:10:38.133Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:37.934610844Z","target":"phd_framework::test_vm","line":541,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","source":"migration_from_base_and_back","target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2352025-03-10T23:10:38.158Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:37.934705436Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","migration_id":"7b1591da-2b1e-4fff-899b-fd6e6c36d903","source":"migration_from_base_and_back","elapsed_milliseconds":3147,"target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2362025-03-10T23:10:38.158Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:37.934782348Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65","elapsed_milliseconds":3686,"source":"migration_from_base_and_back","target_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2372025-03-10T23:10:38.158Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:37.936437479Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2382025-03-10T23:10:38.158Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:37.936659384Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2392025-03-10T23:10:38.158Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:37.936718925Z","target":"phd_framework::test_vm","line":779,"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","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2402025-03-10T23:10:38.158Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:37.937299286Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2412025-03-10T23:10:38.239Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.04020165Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":103,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"9b3b3d9f-4f77-40a9-847b-5c1dc09e4a65"}
2422025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.040624258Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":103,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2432025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.040791581Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2442025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.040851082Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2452025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.063587086Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2462025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.063702268Z","target":"phd_framework::lifecycle","line":73,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__BASE_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2472025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.06381149Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2482025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.063898022Z","target":"phd_framework::test_vm","line":211,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","vm_name":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2492025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.063991844Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/699c2d2c5e97e63733ab85fce044388baefe882761373e5c02190990dd286770/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2502025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.064038585Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/699c2d2c5e97e63733ab85fce044388baefe882761373e5c02190990dd286770/propolis-server\"","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2512025-03-10T23:10:38.263Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.064078135Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2522025-03-10T23:10:38.288Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 871","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.078617233Z","target":"phd_framework::test_vm::server","line":107,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2532025-03-10T23:10:38.288Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.078833997Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":14,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2542025-03-10T23:10:38.288Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.078941419Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","source":"migration_from_base_and_back_lifecycle_0","target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2552025-03-10T23:10:38.288Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.07899759Z","target":"phd_framework::test_vm","line":507,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"c52b8e0a-5abc-452e-a5cc-f3b45c87cbec","timeout_duration":"45s","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","source":"migration_from_base_and_back_lifecycle_0","target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2562025-03-10T23:10:38.288Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.079053331Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2572025-03-10T23:10:38.288Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.079459979Z","target":"phd_framework::test_vm","line":320,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2582025-03-10T23:10:38.816Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.617197453Z","target":"phd_framework::test_vm","line":379,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 335f4b7a-3418-417a-8e57-cabce35da6a6, metadata: InstanceMetadata { project_id: 15ba45b8-4f53-4512-950f-e62eb49080da, silo_id: f1211c9e-be87-4d22-acc5-5eda13de6d8a, sled_id: 6b4e6775-cc19-4cf0-a875-68def212d1de, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"6b4e6775-cc19-4cf0-a875-68def212d1de\" }, name: \"phd-vm-335f4b7a-3418-417a-8e57-cabce35da6a6\" }, state: Migrating }","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2592025-03-10T23:10:38.840Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.617303405Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","elapsed_milliseconds":538,"vm":"migration_from_base_and_back_lifecycle_1"}
2602025-03-10T23:10:38.840Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:38.617353786Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","migration_id":"c52b8e0a-5abc-452e-a5cc-f3b45c87cbec","source":"migration_from_base_and_back_lifecycle_0","target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2612025-03-10T23:10:41.355Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:41.156635413Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7807}}"}
2622025-03-10T23:10:42.853Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.653981953Z","target":"phd_framework::test_vm","line":541,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","source":"migration_from_base_and_back_lifecycle_0","target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2632025-03-10T23:10:42.877Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.654077215Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","migration_id":"c52b8e0a-5abc-452e-a5cc-f3b45c87cbec","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":4036,"target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2642025-03-10T23:10:42.877Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.654140476Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b","elapsed_milliseconds":4575,"source":"migration_from_base_and_back_lifecycle_0","target_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2652025-03-10T23:10:42.877Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.655531043Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2662025-03-10T23:10:42.877Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.655684335Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2672025-03-10T23:10:42.877Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.655727266Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2682025-03-10T23:10:42.878Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.656590753Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2692025-03-10T23:10:42.959Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.760208921Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":104,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"c5af77a0-13e2-4664-a9c1-7a757bc3c83b"}
2702025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.760644209Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":104,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2712025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.760814422Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2722025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.760874533Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2732025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.783333592Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2742025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.783392813Z","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"}
2752025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.783453364Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2762025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.783495165Z","target":"phd_framework::test_vm","line":211,"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\" }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2772025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.783542426Z","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"}
2782025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.783585167Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9006","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2792025-03-10T23:10:42.983Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.783622817Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2802025-03-10T23:10:43.008Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 873","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.800248925Z","target":"phd_framework::test_vm::server","line":107,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2812025-03-10T23:10:43.008Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.800456029Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":16,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2822025-03-10T23:10:43.008Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.800563041Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","source":"migration_from_base_and_back_lifecycle_1","target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2832025-03-10T23:10:43.008Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.800631492Z","target":"phd_framework::test_vm","line":507,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"2b4eec07-6ba1-4f99-9d70-aba6d9b6dde7","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","source":"migration_from_base_and_back_lifecycle_1","target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2842025-03-10T23:10:43.008Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.800718694Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2852025-03-10T23:10:43.008Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:42.801181863Z","target":"phd_framework::test_vm","line":320,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2862025-03-10T23:10:43.283Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:43.084696494Z","target":"phd_framework::test_vm","line":379,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 32d900ff-dea5-407f-bbd7-9d95ea20fc1f, metadata: InstanceMetadata { project_id: 15ba45b8-4f53-4512-950f-e62eb49080da, silo_id: f1211c9e-be87-4d22-acc5-5eda13de6d8a, sled_id: c84d43f0-c66e-4a47-abc7-473ac218fb34, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"c84d43f0-c66e-4a47-abc7-473ac218fb34\" }, name: \"phd-vm-32d900ff-dea5-407f-bbd7-9d95ea20fc1f\" }, state: Migrating }","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2872025-03-10T23:10:43.308Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:43.084795746Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","elapsed_milliseconds":284,"vm":"migration_from_base_and_back_lifecycle_2"}
2882025-03-10T23:10:43.308Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:43.084844567Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","migration_id":"2b4eec07-6ba1-4f99-9d70-aba6d9b6dde7","source":"migration_from_base_and_back_lifecycle_1","target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2892025-03-10T23:10:45.742Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.543679109Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7854}}"}
2902025-03-10T23:10:46.090Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.891016218Z","target":"phd_framework::test_vm","line":541,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","source":"migration_from_base_and_back_lifecycle_1","target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2912025-03-10T23:10:46.090Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.891069559Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","migration_id":"2b4eec07-6ba1-4f99-9d70-aba6d9b6dde7","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":2806,"target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2922025-03-10T23:10:46.114Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.89111572Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"335f4b7a-3418-417a-8e57-cabce35da6a6","elapsed_milliseconds":3090,"source":"migration_from_base_and_back_lifecycle_1","target_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2932025-03-10T23:10:46.114Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.892292043Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2942025-03-10T23:10:46.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.892472836Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2952025-03-10T23:10:46.115Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.892520487Z","target":"phd_framework::test_vm","line":779,"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","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2962025-03-10T23:10:46.115Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.893117978Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2972025-03-10T23:10:46.193Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.994604295Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":102,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"335f4b7a-3418-417a-8e57-cabce35da6a6"}
2982025-03-10T23:10:46.217Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.995207537Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":102,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
2992025-03-10T23:10:46.217Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.99534543Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3002025-03-10T23:10:46.217Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:45.995394271Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3012025-03-10T23:10:46.218Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.018148275Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3022025-03-10T23:10:46.218Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.018255607Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3032025-03-10T23:10:46.218Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.01842375Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3042025-03-10T23:10:46.218Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.018518492Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":16239}
3052025-03-10T23:10:46.218Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.018507992Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3062025-03-10T23:10:46.218Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.018574643Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3072025-03-10T23:10:46.242Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.019271416Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3082025-03-10T23:10:46.793Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.594664529Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3092025-03-10T23:10:46.896Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.697797547Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3102025-03-10T23:10:46.921Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.697864709Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-28318da7-b1bd-4847-ba88-9fa5c098f3fb\"]","verb":"destroy","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3112025-03-10T23:10:46.945Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.732535641Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3122025-03-10T23:10:46.945Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.732588202Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-4ff0d69b-8e0d-47df-bfcd-4b28b7590ca5\"]","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3132025-03-10T23:10:46.969Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.758467265Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":740,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"32d900ff-dea5-407f-bbd7-9d95ea20fc1f"}
3142025-03-10T23:10:46.969Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.758516256Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":90485,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3152025-03-10T23:10:46.969Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.75871668Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":740}
3162025-03-10T23:10:46.969Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.758770051Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3172025-03-10T23:10:46.969Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.758800542Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3182025-03-10T23:10:46.969Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.758828252Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3192025-03-10T23:10:46.969Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.759000796Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
3202025-03-10T23:10:46.969Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.759082187Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::serial_history"}
3212025-03-10T23:10:46.969Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.759131508Z","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"}
3222025-03-10T23:10:46.970Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.759176079Z","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"}
3232025-03-10T23:10:46.970Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.7592213Z","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"}
3242025-03-10T23:10:46.994Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.779786012Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 687M 1.80T 687M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
3252025-03-10T23:10:46.994Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.779885054Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-357362d9-4558-4215-bb17-8fce2ffe4ea5\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::serial_history"}
3262025-03-10T23:10:47.018Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.805909821Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-357362d9-4558-4215-bb17-8fce2ffe4ea5\", \"phd-artifacts/phd-clone-bc022440-3bec-4648-bfff-1da654245650\"]","path":"phd_tests::migrate::from_base::serial_history"}
3272025-03-10T23:10:47.043Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.830512651Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-bc022440-3bec-4648-bfff-1da654245650\"]","path":"phd_tests::migrate::from_base::serial_history"}
3282025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.848699148Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-bc022440-3bec-4648-bfff-1da654245650 0B 1.80T 687M /phd-artifacts/phd-clone-bc022440-3bec-4648-bfff-1da654245650\n","path":"phd_tests::migrate::from_base::serial_history"}
3292025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.849366431Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3302025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.849421152Z","target":"phd_framework::test_vm","line":211,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
3312025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.849473002Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/699c2d2c5e97e63733ab85fce044388baefe882761373e5c02190990dd286770/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
3322025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.849526763Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/699c2d2c5e97e63733ab85fce044388baefe882761373e5c02190990dd286770/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
3332025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.849566674Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stdout_path":"\"/tmp/propolis-phd/migration_serial_history_base.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_serial_history_base.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
3342025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 882","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.860692897Z","target":"phd_framework::test_vm::server","line":107,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
3352025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.860988992Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::serial_history"}
3362025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.861123395Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3372025-03-10T23:10:47.067Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:46.861638505Z","target":"phd_framework::test_vm","line":320,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3382025-03-10T23:10:47.625Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.426427845Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3392025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.426845813Z","target":"phd_framework::test_vm","line":379,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 8580f384-0656-44ae-9e46-0f9fbcfd931e, metadata: InstanceMetadata { project_id: 77166572-3e09-4bd0-bcca-d12dc789ef7d, silo_id: fd0d540b-82c5-4335-a14a-44ba3985a8a9, sled_id: 339a02c0-061d-49db-b394-9f47a6b303d0, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"339a02c0-061d-49db-b394-9f47a6b303d0\" }, name: \"phd-vm-8580f384-0656-44ae-9e46-0f9fbcfd931e\" }, state: Creating }","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3402025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.426910854Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":565,"vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3412025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.426969965Z","target":"phd_framework::test_vm","line":440,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3422025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.427009046Z","target":"phd_framework::test_vm","line":445,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3432025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.427539156Z","target":"phd_framework::test_vm","line":440,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3442025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.427598367Z","target":"phd_framework::test_vm","line":757,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3452025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.427641018Z","target":"phd_framework::test_vm","line":706,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_serial_history_base","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history"}
3462025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.427674929Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
3472025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.427706979Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3482025-03-10T23:10:47.671Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:47.42774036Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3492025-03-10T23:10:51.772Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.572835427Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4145,"vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3502025-03-10T23:10:51.772Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.572905898Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
3512025-03-10T23:10:51.796Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.573067432Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3522025-03-10T23:10:51.796Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.573114753Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3532025-03-10T23:10:51.796Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.573149053Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3542025-03-10T23:10:51.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.590931073Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":17,"vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3552025-03-10T23:10:51.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.591043775Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3562025-03-10T23:10:51.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.591361801Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3572025-03-10T23:10:51.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.591469803Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3582025-03-10T23:10:51.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.591552394Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3592025-03-10T23:10:51.823Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.624165507Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3602025-03-10T23:10:51.823Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.624231228Z","target":"phd_framework::test_vm","line":754,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3612025-03-10T23:10:51.823Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.624272809Z","target":"phd_framework::test_vm","line":757,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4196,"path":"phd_tests::migrate::from_base::serial_history"}
3622025-03-10T23:10:51.823Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.624430202Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3632025-03-10T23:10:51.823Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.624519984Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"echo hello from the source VM!","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3642025-03-10T23:10:51.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.634843851Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3652025-03-10T23:10:51.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.634976393Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3662025-03-10T23:10:51.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.635028314Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3672025-03-10T23:10:51.872Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.667609916Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3682025-03-10T23:10:51.872Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.672362457Z","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"}
3692025-03-10T23:10:51.872Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.672424018Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3702025-03-10T23:10:51.872Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.672466739Z","target":"phd_framework::test_vm","line":211,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
3712025-03-10T23:10:51.872Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.67251093Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
3722025-03-10T23:10:51.872Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.67255132Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
3732025-03-10T23:10:51.872Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.672586911Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stdout_path":"\"/tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::serial_history"}
3742025-03-10T23:10:51.897Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 883","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.688440374Z","target":"phd_framework::test_vm::server","line":107,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::serial_history"}
3752025-03-10T23:10:51.897Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.688643568Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":16,"path":"phd_tests::migrate::from_base::serial_history"}
3762025-03-10T23:10:51.897Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.688738389Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history"}
3772025-03-10T23:10:51.897Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.688798741Z","target":"phd_framework::test_vm","line":507,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"0d2d7829-fa4b-414f-aed2-d0d5e917154a","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history"}
3782025-03-10T23:10:51.897Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.688867912Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3792025-03-10T23:10:51.897Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:51.689346881Z","target":"phd_framework::test_vm","line":320,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","target":"migration_serial_history_base_lifecycle_0","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3802025-03-10T23:10:52.332Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:52.133740203Z","target":"phd_framework::test_vm","line":379,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 3feddb34-bc83-45a4-b7ff-abb31b49b419, metadata: InstanceMetadata { project_id: 77166572-3e09-4bd0-bcca-d12dc789ef7d, silo_id: fd0d540b-82c5-4335-a14a-44ba3985a8a9, sled_id: 1b36ecb9-b84c-45e2-8abf-577ac0de6687, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"1b36ecb9-b84c-45e2-8abf-577ac0de6687\" }, name: \"phd-vm-3feddb34-bc83-45a4-b7ff-abb31b49b419\" }, state: Migrating }","target":"migration_serial_history_base_lifecycle_0","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3812025-03-10T23:10:52.357Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:52.133849735Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":444,"source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","vm":"migration_serial_history_base_lifecycle_0","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history"}
3822025-03-10T23:10:52.357Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:52.133906496Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","migration_id":"0d2d7829-fa4b-414f-aed2-d0d5e917154a","source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history"}
3832025-03-10T23:10:54.807Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:54.608906697Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7727}}"}
3842025-03-10T23:10:56.496Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.29713144Z","target":"phd_framework::test_vm","line":541,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history"}
3852025-03-10T23:10:56.496Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.297180361Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":4163,"migration_id":"0d2d7829-fa4b-414f-aed2-d0d5e917154a","source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history"}
3862025-03-10T23:10:56.520Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.297237722Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":4608,"source":"migration_serial_history_base","source_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","target_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history"}
3872025-03-10T23:10:56.520Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.298671289Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3882025-03-10T23:10:56.520Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.299802941Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3892025-03-10T23:10:56.598Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.399918162Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":101,"vm_id":"8580f384-0656-44ae-9e46-0f9fbcfd931e","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3902025-03-10T23:10:56.623Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.402630923Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3912025-03-10T23:10:56.623Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.402877708Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3922025-03-10T23:10:56.623Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.402907869Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3932025-03-10T23:10:56.623Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.4029746Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3942025-03-10T23:10:56.623Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.403021931Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":8976}
3952025-03-10T23:10:56.623Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.40400761Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3962025-03-10T23:10:56.960Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.761725878Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3972025-03-10T23:10:57.065Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.86663104Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3982025-03-10T23:10:57.089Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.866724972Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-bc022440-3bec-4648-bfff-1da654245650\"]","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3992025-03-10T23:10:57.114Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.90121416Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
4002025-03-10T23:10:57.114Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.901273411Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-357362d9-4558-4215-bb17-8fce2ffe4ea5\"]","verb":"destroy","vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
4012025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.927800087Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":524,"vm_id":"3feddb34-bc83-45a4-b7ff-abb31b49b419","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
4022025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.927844908Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":10168,"path":"phd_tests::migrate::from_base::serial_history"}
4032025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.928090403Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":525}
4042025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.928153194Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
4052025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.928185245Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
4062025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.928211786Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4072025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.928401409Z","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"}
4082025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.928494071Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4092025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.928536772Z","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"}
4102025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.928583073Z","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"}
4112025-03-10T23:10:57.138Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.928630223Z","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"}
4122025-03-10T23:10:57.163Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.947135327Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 688M 1.80T 687M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4132025-03-10T23:10:57.163Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.94728771Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-7c7bf509-b8de-4337-b3d5-54a43c0edf9c\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4142025-03-10T23:10:57.187Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.970058184Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-7c7bf509-b8de-4337-b3d5-54a43c0edf9c\", \"phd-artifacts/phd-clone-543c0442-0b98-4f5a-aa66-40da569a894a\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4152025-03-10T23:10:57.211Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:56.991712357Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-543c0442-0b98-4f5a-aa66-40da569a894a\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4162025-03-10T23:10:57.211Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.008957126Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-543c0442-0b98-4f5a-aa66-40da569a894a 0B 1.80T 687M /phd-artifacts/phd-clone-543c0442-0b98-4f5a-aa66-40da569a894a\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4172025-03-10T23:10:57.211Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.009605388Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4182025-03-10T23:10:57.211Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.00966227Z","target":"phd_framework::test_vm","line":211,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","vm_name":"migration_from_base","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4192025-03-10T23:10:57.211Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.009713401Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/699c2d2c5e97e63733ab85fce044388baefe882761373e5c02190990dd286770/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4202025-03-10T23:10:57.211Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.009768452Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_path":"\"/phd-artifacts/699c2d2c5e97e63733ab85fce044388baefe882761373e5c02190990dd286770/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4212025-03-10T23:10:57.211Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.009811312Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stderr_path":"\"/tmp/propolis-phd/migration_from_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4222025-03-10T23:10:57.236Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 892","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.020044668Z","target":"phd_framework::test_vm::server","line":107,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4232025-03-10T23:10:57.236Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.020246942Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10}
4242025-03-10T23:10:57.236Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.020328413Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4252025-03-10T23:10:57.236Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.020863603Z","target":"phd_framework::test_vm","line":320,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4262025-03-10T23:10:57.980Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.781591874Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
4272025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.782052912Z","target":"phd_framework::test_vm","line":379,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 12a2ab03-0365-4de1-a299-311233471415, metadata: InstanceMetadata { project_id: b51cfd82-859b-41d3-8cf1-c64a22b8bc2e, silo_id: b28dc360-1f77-4cb4-9cf9-c534106f9384, sled_id: df17d0c9-848e-412f-a6e6-deedf7a2e229, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"df17d0c9-848e-412f-a6e6-deedf7a2e229\" }, name: \"phd-vm-12a2ab03-0365-4de1-a299-311233471415\" }, state: Creating }","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4282025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.782131434Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":761,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4292025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.782197795Z","target":"phd_framework::test_vm","line":440,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4302025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.782236836Z","target":"phd_framework::test_vm","line":445,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4312025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.782804137Z","target":"phd_framework::test_vm","line":440,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4322025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.782863808Z","target":"phd_framework::test_vm","line":757,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4332025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.782906879Z","target":"phd_framework::test_vm","line":706,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm_id":"12a2ab03-0365-4de1-a299-311233471415","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4342025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.782939819Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4352025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.78297225Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4362025-03-10T23:10:58.027Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:10:57.783006041Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4372025-03-10T23:11:02.179Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.980720002Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":4197,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4382025-03-10T23:11:02.179Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.980796534Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4392025-03-10T23:11:02.204Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.980968737Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4402025-03-10T23:11:02.204Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.981018248Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4412025-03-10T23:11:02.204Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.981053099Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4422025-03-10T23:11:02.204Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.99892386Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":17,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4432025-03-10T23:11:02.204Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.999029622Z","target":"phd_framework::test_vm","line":714,"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"}
4442025-03-10T23:11:02.204Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.999416269Z","target":"phd_framework::test_vm","line":714,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4452025-03-10T23:11:02.204Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.999539442Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4462025-03-10T23:11:02.204Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:01.999622073Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4472025-03-10T23:11:02.231Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.032248496Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4482025-03-10T23:11:02.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.032306577Z","target":"phd_framework::test_vm","line":754,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4492025-03-10T23:11:02.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.032344338Z","target":"phd_framework::test_vm","line":757,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4249}
4502025-03-10T23:11:02.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.03247251Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4512025-03-10T23:11:02.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.032524291Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4522025-03-10T23:11:02.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.042909659Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4532025-03-10T23:11:02.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.043103303Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4542025-03-10T23:11:02.255Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.043177564Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4552025-03-10T23:11:02.279Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.064647714Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":21,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4562025-03-10T23:11:02.280Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.064797357Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4572025-03-10T23:11:02.280Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.064847618Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4582025-03-10T23:11:02.280Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.076216425Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4592025-03-10T23:11:02.280Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.076408029Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4602025-03-10T23:11:02.280Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.07648089Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4612025-03-10T23:11:02.308Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.109296446Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4622025-03-10T23:11:02.332Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.10948988Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4632025-03-10T23:11:02.332Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.109564202Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4642025-03-10T23:11:02.332Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.11996167Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4652025-03-10T23:11:02.332Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.120159784Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4662025-03-10T23:11:02.332Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.120235825Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4672025-03-10T23:11:02.356Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.142838837Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4682025-03-10T23:11:02.356Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.142985189Z","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"}
4692025-03-10T23:11:02.356Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.143104372Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4702025-03-10T23:11:02.356Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.143185413Z","target":"phd_framework::test_vm","line":211,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4712025-03-10T23:11:02.356Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.143273095Z","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"}
4722025-03-10T23:11:02.356Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.143351216Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4732025-03-10T23:11:02.356Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.143421108Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4742025-03-10T23:11:02.381Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 893","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.158161409Z","target":"phd_framework::test_vm::server","line":107,"file":"phd-tests/framework/src/test_vm/server.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4752025-03-10T23:11:02.381Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.158361023Z","target":"phd_framework::test_vm","line":193,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":15}
4762025-03-10T23:11:02.381Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.158445655Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"12a2ab03-0365-4de1-a299-311233471415"}
4772025-03-10T23:11:02.381Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.158521896Z","target":"phd_framework::test_vm","line":507,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"bd390dcb-630e-4e4b-a225-e907a356881c","timeout_duration":"45s","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"12a2ab03-0365-4de1-a299-311233471415"}
4782025-03-10T23:11:02.381Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.158585577Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","vm":"migration_from_base_lifecycle_0","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"12a2ab03-0365-4de1-a299-311233471415"}
4792025-03-10T23:11:02.381Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.159038846Z","target":"phd_framework::test_vm","line":320,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","vm":"migration_from_base_lifecycle_0","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"12a2ab03-0365-4de1-a299-311233471415"}
4802025-03-10T23:11:03.051Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.85289099Z","target":"phd_framework::test_vm","line":379,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: ec6eeac3-084b-48f4-a2a4-94c6d4d5e409, metadata: InstanceMetadata { project_id: b51cfd82-859b-41d3-8cf1-c64a22b8bc2e, silo_id: b28dc360-1f77-4cb4-9cf9-c534106f9384, sled_id: 1c59a193-1a27-460e-ad0a-311a16a89ca6, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"1c59a193-1a27-460e-ad0a-311a16a89ca6\" }, name: \"phd-vm-ec6eeac3-084b-48f4-a2a4-94c6d4d5e409\" }, state: Migrating }","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","vm":"migration_from_base_lifecycle_0","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"12a2ab03-0365-4de1-a299-311233471415"}
4812025-03-10T23:11:03.076Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.853013132Z","target":"phd_framework::test_vm","line":276,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","target":"migration_from_base_lifecycle_0","source_id":"12a2ab03-0365-4de1-a299-311233471415","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","elapsed_milliseconds":694,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4822025-03-10T23:11:03.076Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:02.853064093Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","migration_id":"bd390dcb-630e-4e4b-a225-e907a356881c","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"12a2ab03-0365-4de1-a299-311233471415"}
4832025-03-10T23:11:05.520Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:05.32158735Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7760}}"}
4842025-03-10T23:11:06.211Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:06.012077489Z","target":"phd_framework::test_vm","line":541,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"12a2ab03-0365-4de1-a299-311233471415"}
4852025-03-10T23:11:06.211Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:06.01216211Z","target":"phd_framework::test_vm","line":528,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","elapsed_milliseconds":3159,"migration_id":"bd390dcb-630e-4e4b-a225-e907a356881c","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"12a2ab03-0365-4de1-a299-311233471415"}
4862025-03-10T23:11:06.235Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:06.012212701Z","target":"phd_framework::test_vm","line":474,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_lifecycle_0","source":"migration_from_base","target_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","elapsed_milliseconds":3853,"path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"12a2ab03-0365-4de1-a299-311233471415"}
4872025-03-10T23:11:06.235Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:06.013397424Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4882025-03-10T23:11:06.235Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:06.013558537Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
4892025-03-10T23:11:06.235Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:06.013611968Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
4902025-03-10T23:11:06.235Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:06.014325352Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm_id":"12a2ab03-0365-4de1-a299-311233471415","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4912025-03-10T23:11:06.313Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:06.114265769Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","elapsed_milliseconds":100,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"12a2ab03-0365-4de1-a299-311233471415"}
4922025-03-10T23:11:08.824Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.625312158Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":2611,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409"}
4932025-03-10T23:11:08.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.625508732Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
4942025-03-10T23:11:08.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.625570763Z","target":"phd_framework::test_vm","line":779,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
4952025-03-10T23:11:08.872Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.657547073Z","target":"phd_framework::test_vm","line":772,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":31,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409"}
4962025-03-10T23:11:08.872Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.657727476Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
4972025-03-10T23:11:08.872Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.657963841Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
4982025-03-10T23:11:08.872Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.658081943Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10876}
4992025-03-10T23:11:08.872Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.658127454Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
5002025-03-10T23:11:08.872Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.658248586Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
5012025-03-10T23:11:08.872Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:08.658896519Z","target":"phd_framework::test_vm","line":1052,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
5022025-03-10T23:11:09.534Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.335047175Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
5032025-03-10T23:11:09.636Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.437173764Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
5042025-03-10T23:11:09.660Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.437245665Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-543c0442-0b98-4f5a-aa66-40da569a894a\"]","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
5052025-03-10T23:11:09.684Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.471633651Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
5062025-03-10T23:11:09.684Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.471701693Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-7c7bf509-b8de-4337-b3d5-54a43c0edf9c\"]","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0"}
5072025-03-10T23:11:09.708Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.495956826Z","target":"phd_framework::test_vm","line":1029,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","elapsed_milliseconds":838,"path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"ec6eeac3-084b-48f4-a2a4-94c6d4d5e409"}
5082025-03-10T23:11:09.708Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.496001277Z","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":12567}
5092025-03-10T23:11:09.708Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.496218941Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":837}
5102025-03-10T23:11:09.708Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.496288062Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5112025-03-10T23:11:09.708Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.496317693Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5122025-03-10T23:11:09.708Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 113.22s
5132025-03-10T23:11:09.708Z
5142025-03-10T23:11:09.708Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"sock","pid":863,"time":"2025-03-10T23:11:09.496388234Z","target":"phd_runner","line":40,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5152025-03-10T23:11:09.770Z
5162025-03-10T23:11:09.795Zreal 1:53.924877234
5172025-03-10T23:11:09.795Zuser 37.380226819
5182025-03-10T23:11:09.795Zsys 15.028309633
5192025-03-10T23:11:09.795Ztrap 0.004522280
5202025-03-10T23:11:09.795Ztflt 0.001045627
5212025-03-10T23:11:09.795Zdflt 0.000336452
5222025-03-10T23:11:09.795Zkflt 0.000116438
5232025-03-10T23:11:09.795Zlock 1:50:41.381697755
5242025-03-10T23:11:09.795Zslp 4:31.382224409
5252025-03-10T23:11:09.798Zlat 0.422310068
5262025-03-10T23:11:09.798Zstop 18.088756919
5272025-03-10T23:11:09.798Z+ failcount=0
5282025-03-10T23:11:09.798Z+ set -e
5292025-03-10T23:11:09.798Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log /tmp/propolis-phd/migration_from_base_and_back.serial.log /tmp/propolis-phd/migration_from_base_and_back.stderr.log /tmp/propolis-phd/migration_from_base_and_back.stdout.log /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log /tmp/propolis-phd/migration_from_base.serial.log /tmp/propolis-phd/migration_from_base.stderr.log /tmp/propolis-phd/migration_from_base.stdout.log /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log /tmp/propolis-phd/migration_serial_history_base.serial.log /tmp/propolis-phd/migration_serial_history_base.stderr.log /tmp/propolis-phd/migration_serial_history_base.stdout.log
5302025-03-10T23:11:09.798ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5312025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5322025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log 230K
5332025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5342025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log 231K
5352025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5362025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log 143K
5372025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_and_back.serial.log 7K
5382025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_and_back.stderr.log 0K
5392025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_and_back.stdout.log 138K
5402025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log 0K
5412025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log 143K
5422025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base.serial.log 7K
5432025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base.stderr.log 0K
5442025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_from_base.stdout.log 137K
5452025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log 0K
5462025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log 144K
5472025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_serial_history_base.serial.log 7K
5482025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_serial_history_base.stderr.log 0K
5492025-03-10T23:11:09.799Za /tmp/propolis-phd/migration_serial_history_base.stdout.log 139K
5502025-03-10T23:11:09.799Z+ exitcode=0
5512025-03-10T23:11:09.799Z+ '[' 0 -eq 0 ']'
5522025-03-10T23:11:09.799Z+ echo
5532025-03-10T23:11:09.799Z
5542025-03-10T23:11:09.799Z+ echo 'ALL TESTS PASSED'
5552025-03-10T23:11:09.799ZALL TESTS PASSED
5562025-03-10T23:11:09.799Z+ echo
5572025-03-10T23:11:09.799Z
5582025-03-10T23:11:09.800Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5592025-03-10T23:11:09.800Z+ read
5602025-03-10T23:11:09.800Z+ exit 0
5612025-03-10T23:11:09.800Zprocess exited: duration 124136 ms, exit code 0
 
5622025-03-10T23:11:09.877Zfound 2 output files
5632025-03-10T23:11:09.877Zuploading: /tmp/phd-runner.log (162804 bytes)
5642025-03-10T23:11:11.041Zuploaded: /tmp/phd-runner.log
5652025-03-10T23:11:11.041Zuploading: /tmp/phd-tmp-files.tar.gz (102536 bytes)
5662025-03-10T23:11:12.245Zuploaded: /tmp/phd-tmp-files.tar.gz