01JH3VSN0RA8W8W9BB3NM8GVJE: 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: 01JH3VT09F9EBM4QKJNCKKJQP4

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12025-01-08T21:13:36.530Zjob dependencies complete; ready to run (waiting for 7 m 40 s)
22025-01-08T21:29:46.539Zjob assigned to worker 01JH3X45J07G50R18G1Q5X13T2 [factory lab, buskin/12915] (queued for 16 m 10 s)
32025-01-08T21:29:46.607Zhttp://172.20.0.5:9969/ipxe/buskin... ok
42025-01-08T21:29:46.662Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/kernel/amd64/unix... ok
52025-01-08T21:29:46.695Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive... ok
62025-01-08T21:29:46.730Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive.hash... ok
72025-01-08T21:29:46.764Zhttp://172.20.0.5:9969/postboot/buskin... ok
82025-01-08T21:29:46.797ZwcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U
92025-01-08T21:29:46.832Zcpu0: microcode has been updated from version 0xa001133 to 0xa0011d5
102025-01-08T21:29:46.869ZOxide Helios Version helios-2.0.23032 64-bit
112025-01-08T21:29:46.903ZConfiguring devices.
122025-01-08T21:29:46.936Z##################################################
132025-01-08T21:29:46.969Z#### ############# ##
142025-01-08T21:29:47.004Z### ### ############ ##
152025-01-08T21:29:47.038Z## ### # ## ### ## Oxide Computer Company ##
162025-01-08T21:29:47.072Z## ## ## ### # ### ##
172025-01-08T21:29:47.122Z## # ### #### #### This Station Under ##
182025-01-08T21:29:47.156Z### ### #### # ### Computer Control ##
192025-01-08T21:29:47.189Z#### #### ### ## ##
202025-01-08T21:29:47.223Z##################################################
212025-01-08T21:29:47.256ZHostname: buskin
222025-01-08T21:29:47.289ZLoading smf(7) service descriptions:
232025-01-08T21:29:47.568Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
242025-01-08T21:29:47.655Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
252025-01-08T21:29:47.679Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
262025-01-08T21:29:47.703Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
272025-01-08T21:29:47.703Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
282025-01-08T21:29:59.491Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
292025-01-08T21:29:59.491Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
302025-01-08T21:29:59.550Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
312025-01-08T21:29:59.550Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
322025-01-08T21:30:23.208Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
332025-01-08T21:30:23.232Zstarting task 0: "setup"
342025-01-08T21:30:23.233Z++ uname -s
352025-01-08T21:30:23.233Z+ kern=SunOS
362025-01-08T21:30:23.233Z+ case "$kern" in
372025-01-08T21:30:23.233Z+ groupadd -g 12345 build
382025-01-08T21:30:23.233Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
392025-01-08T21:30:25.225Z+ zfs create -o mountpoint=/work rpool/work
402025-01-08T21:30:25.265Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
412025-01-08T21:30:25.290Z+ home_fs=zfs
422025-01-08T21:30:25.290Z+ [[ zfs == autofs ]]
432025-01-08T21:30:25.291Z+ mkdir -p /home/build
442025-01-08T21:30:25.291Z+ chown build:build /home/build /work
452025-01-08T21:30:27.274Z+ chmod 0700 /home/build /work
462025-01-08T21:30:27.299Zprocess exited: duration 4068 ms, exit code 0
 
472025-01-08T21:30:27.348Zstarting task 1: "authentication"
482025-01-08T21:30:27.416Zprocess exited: duration 47 ms, exit code 0
 
492025-01-08T21:30:27.468Zstarting task 2: "build"
502025-01-08T21:30:27.492Z+ indir=/input
512025-01-08T21:30:27.492Z+ indir_suffix='phd-build/out/*.tar.gz'
522025-01-08T21:30:27.492Z+ phddir=/work/phd-test
532025-01-08T21:30:27.492Z+ pfexec zpool create -f phd-artifacts c1t1d0 c2t1d0
542025-01-08T21:30:27.620Z+ artifactdir=/phd-artifacts
552025-01-08T21:30:27.620Z+ banner Inputs
562025-01-08T21:30:27.646Z ###
572025-01-08T21:30:27.646Z # # # ##### # # ##### ####
582025-01-08T21:30:27.646Z # ## # # # # # # #
592025-01-08T21:30:27.646Z # # # # # # # # # ####
602025-01-08T21:30:27.646Z # # # # ##### # # # #
612025-01-08T21:30:27.646Z # # ## # # # # # #
622025-01-08T21:30:27.646Z ### # # # #### # ####
632025-01-08T21:30:27.646Z
642025-01-08T21:30:27.646Z+ find /input -ls
652025-01-08T21:30:27.646Z 34 1 drwxr-xr-x 3 root root 3 Jan 8 21:29 /input
662025-01-08T21:30:27.646Z 2 1 drwxr-xr-x 3 root root 3 Jan 8 21:29 /input/phd-build
672025-01-08T21:30:27.646Z 3 2 drwxr-xr-x 2 root root 7 Jan 8 21:29 /input/phd-build/out
682025-01-08T21:30:27.646Z 256 1 -rw-r--r-- 1 root root 65 Jan 8 21:29 /input/phd-build/out/propolis-server-debug.sha256.txt
692025-01-08T21:30:27.646Z 128 2 -rw-r--r-- 1 root root 1746 Jan 8 21:29 /input/phd-build/out/phd-run-with-args.sh
702025-01-08T21:30:27.647Z 130 67220 -rw-r--r-- 1 root root 68788842 Jan 8 21:29 /input/phd-build/out/phd-runner.tar.gz
712025-01-08T21:30:27.647Z 257 135157 -rw-r--r-- 1 root root 138309180 Jan 8 21:30 /input/phd-build/out/propolis-server-debug.tar.gz
722025-01-08T21:30:27.647Z 129 1 -rw-r--r-- 1 root root 65 Jan 8 21:29 /input/phd-build/out/phd-runner.sha256.txt
732025-01-08T21:30:27.647Z+ rm -rf /work/phd-test
742025-01-08T21:30:27.647Z+ mkdir /work/phd-test
752025-01-08T21:30:27.647Z+ for p in $indir/$indir_suffix
762025-01-08T21:30:27.647Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
772025-01-08T21:30:29.131ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
782025-01-08T21:30:29.131Zx phd-runner, 244998912 bytes, 478514 tape blocks
792025-01-08T21:30:29.131Zx artifacts.toml, 548 bytes, 2 tape blocks
802025-01-08T21:30:29.155Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
812025-01-08T21:30:30.593Z+ for f in $(tar tf "$p")
822025-01-08T21:30:30.593Z+ chmod +x /work/phd-test/phd-runner
832025-01-08T21:30:30.623Z+ for f in $(tar tf "$p")
842025-01-08T21:30:30.623Z+ chmod +x /work/phd-test/artifacts.toml
852025-01-08T21:30:30.623Z+ for p in $indir/$indir_suffix
862025-01-08T21:30:30.623Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
872025-01-08T21:30:33.764ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
882025-01-08T21:30:33.764Zx propolis-server, 524419984 bytes, 1024258 tape blocks
892025-01-08T21:30:33.788Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
902025-01-08T21:30:36.645Z+ for f in $(tar tf "$p")
912025-01-08T21:30:36.645Z+ chmod +x /work/phd-test/propolis-server
922025-01-08T21:30:36.668Z+ ls /work/phd-test
932025-01-08T21:30:36.668Zartifacts.toml
942025-01-08T21:30:36.668Zphd-runner
952025-01-08T21:30:36.669Zpropolis-server
962025-01-08T21:30:36.669Z+ banner Setup
972025-01-08T21:30:36.669Z #####
982025-01-08T21:30:36.669Z# # ###### ##### # # #####
992025-01-08T21:30:36.669Z# # # # # # #
1002025-01-08T21:30:36.669Z ##### ##### # # # # #
1012025-01-08T21:30:36.669Z # # # # # #####
1022025-01-08T21:30:36.669Z# # # # # # #
1032025-01-08T21:30:36.669Z ##### ###### # #### #
1042025-01-08T21:30:36.669Z
1052025-01-08T21:30:36.669Z+ tmpdir=/tmp/propolis-phd
1062025-01-08T21:30:36.669Z+ '[' '!' -d /tmp/propolis-phd ']'
1072025-01-08T21:30:36.669Z+ mkdir /tmp/propolis-phd
1082025-01-08T21:30:36.669Z+ banner Tests
1092025-01-08T21:30:36.669Z#######
1102025-01-08T21:30:36.669Z # ###### #### ##### ####
1112025-01-08T21:30:36.669Z # # # # #
1122025-01-08T21:30:36.669Z # ##### #### # ####
1132025-01-08T21:30:36.669Z # # # # #
1142025-01-08T21:30:36.669Z # # # # # # #
1152025-01-08T21:30:36.669Z # ###### #### # ####
1162025-01-08T21:30:36.669Z
1172025-01-08T21:30:36.669Z+ runner=/work/phd-test/phd-runner
1182025-01-08T21:30:36.669Z+ artifacts=/work/phd-test/artifacts.toml
1192025-01-08T21:30:36.669Z+ propolis=/work/phd-test/propolis-server
1202025-01-08T21:30:36.669Z+ ls /work/phd-test/phd-runner
1212025-01-08T21:30:36.669Z/work/phd-test/phd-runner
1222025-01-08T21:30:36.669Z+ ls /work/phd-test/artifacts.toml
1232025-01-08T21:30:36.669Z/work/phd-test/artifacts.toml
1242025-01-08T21:30:36.669Z+ ls /work/phd-test/propolis-server
1252025-01-08T21:30:36.669Z/work/phd-test/propolis-server
1262025-01-08T21:30:36.669Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1272025-01-08T21:30:36.669Z+ set +e
1282025-01-08T21:30:36.669Z+ RUST_BACKTRACE=1
1292025-01-08T21:30:36.669Z+ RUST_LOG=info,phd=debug
1302025-01-08T21:30:36.669Z+ 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
1312025-01-08T21:30:36.669Z+ tee /tmp/phd-runner.log
1322025-01-08T21:30:36.694Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:36.392698057Z","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 }"}
1332025-01-08T21:30:36.718Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:36.394983124Z","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: 192, tv_nsec: 285706769 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1342025-01-08T21:30:36.718Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:36.395034855Z","target":"phd_framework::artifacts::store","line":229,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1352025-01-08T21:30:36.718Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:36.395115617Z","target":"phd_framework::artifacts::store","line":313,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"5a41b826171c7d2a8412fa833377ab1df25ee8ec"}
1362025-01-08T21:30:36.718Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:36.39523816Z","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/5a41b826171c7d2a8412fa833377ab1df25ee8ec/crucible-nightly.sha256.txt"}
1372025-01-08T21:30:36.815Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:36.514308161Z","target":"phd_framework::artifacts::store","line":250,"file":"phd-tests/framework/src/artifacts/store.rs"}
1382025-01-08T21:30:37.224Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:36.922878515Z","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/7d941410a52377671e77a0f6cfef3defe67151f7/propolis-server.sha256.txt"}
1392025-01-08T21:30:37.378Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.077032361Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1402025-01-08T21:30:37.403Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.077102413Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1412025-01-08T21:30:37.403Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.077247467Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1422025-01-08T21:30:37.403Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.07734778Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1432025-01-08T21:30:37.404Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.07738168Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1442025-01-08T21:30:37.404Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.077416591Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1452025-01-08T21:30:37.404Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.07776899Z","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"}
1462025-01-08T21:30:37.404Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.078089338Z","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"}
1472025-01-08T21:30:37.404Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.078306443Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/6d92acf0a22718dd4175d7c64dbcf7aaec3740bd/OVMF_CODE.fd","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1482025-01-08T21:30:37.946Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.644559402Z","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"}
1492025-01-08T21:30:37.969Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:30:37.644754017Z","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"}
1502025-01-08T21:31:08.330Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.02861406Z","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"}
1512025-01-08T21:31:08.330Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.028725462Z","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"}
1522025-01-08T21:31:08.353Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.051967842Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 3.31M 1.80T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1532025-01-08T21:31:08.354Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.052199168Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-3ee913e6-d0a8-4e77-a2a1-9d76c17023af\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1542025-01-08T21:31:08.406Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.104457002Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-3ee913e6-d0a8-4e77-a2a1-9d76c17023af\", \"phd-artifacts/phd-clone-91738afe-25af-4871-9715-679a6bf257aa\"]","verb":"clone","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1552025-01-08T21:31:08.429Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.125916438Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-91738afe-25af-4871-9715-679a6bf257aa\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1562025-01-08T21:31:08.453Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.138953943Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-91738afe-25af-4871-9715-679a6bf257aa 0B 1.80T 48.9M /phd-artifacts/phd-clone-91738afe-25af-4871-9715-679a6bf257aa\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1572025-01-08T21:31:08.453Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.139731532Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1582025-01-08T21:31:08.453Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.139787753Z","target":"phd_framework::test_vm","line":210,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1592025-01-08T21:31:08.453Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.139859195Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/f666d8a901a758714220e83a563f3beddc3a14eca1768ca350a9feca05687ef4/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1602025-01-08T21:31:08.453Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:08.139917807Z","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/7d941410a52377671e77a0f6cfef3defe67151f7/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1612025-01-08T21:31:32.473Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:32.17155529Z","target":"phd_framework::artifacts::store","line":162,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/f666d8a901a758714220e83a563f3beddc3a14eca1768ca350a9feca05687ef4/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1622025-01-08T21:31:32.498Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:32.171654762Z","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"}
1632025-01-08T21:31:45.086Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:44.784111919Z","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/f666d8a901a758714220e83a563f3beddc3a14eca1768ca350a9feca05687ef4/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1642025-01-08T21:31:45.110Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:44.784269743Z","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"}
1652025-01-08T21:31:45.133Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 867","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:44.82262989Z","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"}
1662025-01-08T21:31:45.134Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:44.822948378Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":36683}
1672025-01-08T21:31:45.134Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:44.823136043Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1682025-01-08T21:31:45.134Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:44.823867341Z","target":"phd_framework::test_vm","line":319,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1692025-01-08T21:31:45.566Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.264239588Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1702025-01-08T21:31:45.589Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.265126031Z","target":"phd_framework::test_vm","line":378,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 5aa5a60d-da79-4764-b139-9e405a483e74, metadata: InstanceMetadata { project_id: e1f269c3-b018-4894-8845-01fa7b05b5c9, silo_id: 9645d99b-01eb-414c-a016-ef7213d20657, sled_id: 160a70bc-a313-40ae-9571-13c28aee5032, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"160a70bc-a313-40ae-9571-13c28aee5032\" }, name: \"phd-vm-5aa5a60d-da79-4764-b139-9e405a483e74\" }, state: Creating }","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1712025-01-08T21:31:45.590Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.265220073Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":442}
1722025-01-08T21:31:45.590Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.265286905Z","target":"phd_framework::test_vm","line":439,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1732025-01-08T21:31:45.590Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.265328816Z","target":"phd_framework::test_vm","line":444,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1742025-01-08T21:31:45.590Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.265992832Z","target":"phd_framework::test_vm","line":439,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":0}
1752025-01-08T21:31:45.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.266093835Z","target":"phd_framework::test_vm","line":723,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1762025-01-08T21:31:45.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.266140796Z","target":"phd_framework::test_vm","line":672,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1772025-01-08T21:31:45.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.266191667Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1782025-01-08T21:31:45.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.266229608Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1792025-01-08T21:31:45.590Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:45.266266709Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1802025-01-08T21:31:49.802Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.500870815Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4234}
1812025-01-08T21:31:49.802Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.500950607Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1822025-01-08T21:31:49.826Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.501200583Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1832025-01-08T21:31:49.826Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.501249504Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1842025-01-08T21:31:49.826Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.501284455Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1852025-01-08T21:31:49.826Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.519239443Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":17}
1862025-01-08T21:31:49.826Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.519316965Z","target":"phd_framework::test_vm","line":680,"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"}
1872025-01-08T21:31:49.826Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.519494339Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1882025-01-08T21:31:49.827Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.519542671Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1892025-01-08T21:31:49.827Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.519576952Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1902025-01-08T21:31:49.855Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.552193455Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
1912025-01-08T21:31:49.878Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.552299478Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1922025-01-08T21:31:49.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.5523698Z","target":"phd_framework::test_vm","line":723,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4286}
1932025-01-08T21:31:49.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.552653197Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1942025-01-08T21:31:49.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.552727849Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1952025-01-08T21:31:49.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.563093327Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
1962025-01-08T21:31:49.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.563317483Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1972025-01-08T21:31:49.879Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.563400815Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
1982025-01-08T21:31:49.903Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.584890941Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":21}
1992025-01-08T21:31:49.903Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.585022514Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2002025-01-08T21:31:49.903Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.585072556Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2012025-01-08T21:31:49.903Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.595475395Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
2022025-01-08T21:31:49.904Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.59568225Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2032025-01-08T21:31:49.904Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.595752672Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2042025-01-08T21:31:49.927Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.617400122Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":21}
2052025-01-08T21:31:49.927Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.617607198Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2062025-01-08T21:31:49.928Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.617656409Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2072025-01-08T21:31:49.951Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.628969001Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":11}
2082025-01-08T21:31:49.951Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.629097594Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2092025-01-08T21:31:49.951Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.629145795Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2102025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.65057602Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":21}
2112025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.650674332Z","target":"phd_framework::lifecycle","line":74,"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"}
2122025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.650745514Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2132025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.650791235Z","target":"phd_framework::test_vm","line":210,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","vm_name":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2142025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.650856577Z","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"}
2152025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.650909858Z","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"}
2162025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.65095757Z","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"}
2172025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.650999181Z","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_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2182025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 868","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.665256396Z","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"}
2192025-01-08T21:31:49.976Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.665467092Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":14}
2202025-01-08T21:31:49.977Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.665553004Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2212025-01-08T21:31:49.977Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.665607555Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"1d9c1193-c90f-4ec4-b718-41aa38bbc075","timeout_duration":"45s","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2222025-01-08T21:31:49.977Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.665666517Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2232025-01-08T21:31:49.977Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:49.666133368Z","target":"phd_framework::test_vm","line":319,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2242025-01-08T21:31:50.764Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:50.462315893Z","target":"phd_framework::test_vm","line":378,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: a025b48e-fbd4-4deb-b037-41ce7c0a078e, metadata: InstanceMetadata { project_id: e1f269c3-b018-4894-8845-01fa7b05b5c9, silo_id: 9645d99b-01eb-414c-a016-ef7213d20657, sled_id: 3664bafd-71a5-4a47-8c15-367dbd6a6034, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"3664bafd-71a5-4a47-8c15-367dbd6a6034\" }, name: \"phd-vm-a025b48e-fbd4-4deb-b037-41ce7c0a078e\" }, state: Migrating }","source":"migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2252025-01-08T21:31:50.788Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:50.462426585Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":796,"source":"migration_from_base_and_back","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2262025-01-08T21:31:50.788Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:50.462481537Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","migration_id":"1d9c1193-c90f-4ec4-b718-41aa38bbc075","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2272025-01-08T21:31:53.216Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:52.914802544Z","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}}"}
2282025-01-08T21:31:54.353Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:54.051133336Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2292025-01-08T21:31:54.353Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:54.051225309Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","migration_id":"1d9c1193-c90f-4ec4-b718-41aa38bbc075","elapsed_milliseconds":3588,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2302025-01-08T21:31:54.376Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:54.051309801Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back","elapsed_milliseconds":4385,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"5aa5a60d-da79-4764-b139-9e405a483e74","target":"migration_from_base_and_back_lifecycle_0","target_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2312025-01-08T21:31:54.377Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:54.053035304Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2322025-01-08T21:31:54.377Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:54.053261339Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2332025-01-08T21:31:54.377Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:54.053311271Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2342025-01-08T21:31:54.377Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:54.053940236Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74"}
2352025-01-08T21:31:54.486Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:54.184602396Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"5aa5a60d-da79-4764-b139-9e405a483e74","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":131}
2362025-01-08T21:31:56.460Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.158533607Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":2105}
2372025-01-08T21:31:56.484Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.158740543Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2382025-01-08T21:31:56.484Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.158800364Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2392025-01-08T21:31:56.484Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.181318106Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":22}
2402025-01-08T21:31:56.484Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.181402818Z","target":"phd_framework::lifecycle","line":74,"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"}
2412025-01-08T21:31:56.485Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.1814785Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2422025-01-08T21:31:56.485Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.181533021Z","target":"phd_framework::test_vm","line":210,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_1","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2432025-01-08T21:31:56.485Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.181594563Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/f666d8a901a758714220e83a563f3beddc3a14eca1768ca350a9feca05687ef4/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2442025-01-08T21:31:56.485Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.181647764Z","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:9004","server_path":"\"/phd-artifacts/f666d8a901a758714220e83a563f3beddc3a14eca1768ca350a9feca05687ef4/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2452025-01-08T21:31:56.485Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.181692195Z","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"}
2462025-01-08T21:31:56.508Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 870","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.196967226Z","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"}
2472025-01-08T21:31:56.509Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.197229703Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":15}
2482025-01-08T21:31:56.509Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.197350556Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2492025-01-08T21:31:56.509Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.197465849Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"eba417b8-11d3-47ed-83d1-53a39c5999e6","timeout_duration":"45s","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2502025-01-08T21:31:56.509Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.197550031Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2512025-01-08T21:31:56.509Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:56.197944921Z","target":"phd_framework::test_vm","line":319,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance)","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2522025-01-08T21:31:57.305Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:57.003288965Z","target":"phd_framework::test_vm","line":378,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 65f8fa97-57a3-406a-9356-1251b6404182, metadata: InstanceMetadata { project_id: e1f269c3-b018-4894-8845-01fa7b05b5c9, silo_id: 9645d99b-01eb-414c-a016-ef7213d20657, sled_id: c7a9e319-faba-43cd-8680-76b6f7491922, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"c7a9e319-faba-43cd-8680-76b6f7491922\" }, name: \"phd-vm-65f8fa97-57a3-406a-9356-1251b6404182\" }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2532025-01-08T21:31:57.328Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:57.003391197Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":805,"source":"migration_from_base_and_back_lifecycle_0","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2542025-01-08T21:31:57.328Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:57.003440908Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","migration_id":"eba417b8-11d3-47ed-83d1-53a39c5999e6","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2552025-01-08T21:31:59.798Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:31:59.496766268Z","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}}"}
2562025-01-08T21:32:01.428Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.126224614Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2572025-01-08T21:32:01.428Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.126285976Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","migration_id":"eba417b8-11d3-47ed-83d1-53a39c5999e6","elapsed_milliseconds":4122,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2582025-01-08T21:32:01.451Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.126332477Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":4928,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","target":"migration_from_base_and_back_lifecycle_1","target_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2592025-01-08T21:32:01.452Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.127517937Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2602025-01-08T21:32:01.452Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.127700021Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2612025-01-08T21:32:01.452Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.127743662Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2622025-01-08T21:32:01.452Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.128534472Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e"}
2632025-01-08T21:32:01.562Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.260762161Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"a025b48e-fbd4-4deb-b037-41ce7c0a078e","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":133}
2642025-01-08T21:32:01.586Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.261196582Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":133}
2652025-01-08T21:32:01.586Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.261366336Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2662025-01-08T21:32:01.586Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.261422638Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2672025-01-08T21:32:01.610Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.294046681Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
2682025-01-08T21:32:01.610Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.294124223Z","target":"phd_framework::lifecycle","line":74,"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"}
2692025-01-08T21:32:01.610Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.294193175Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2702025-01-08T21:32:01.610Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.294244957Z","target":"phd_framework::test_vm","line":210,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2712025-01-08T21:32:01.610Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.294307538Z","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"}
2722025-01-08T21:32:01.610Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.294359809Z","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:9006","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2732025-01-08T21:32:01.611Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.2944044Z","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_2.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2742025-01-08T21:32:01.635Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 872","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.310145273Z","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"}
2752025-01-08T21:32:01.635Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.310331278Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":16}
2762025-01-08T21:32:01.635Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.31042935Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2772025-01-08T21:32:01.635Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.310484162Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"11108d78-190b-4a34-9541-3262ceab4e2d","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2782025-01-08T21:32:01.635Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.310549093Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2792025-01-08T21:32:01.635Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.310897302Z","target":"phd_framework::test_vm","line":319,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance)","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2802025-01-08T21:32:02.105Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.80379757Z","target":"phd_framework::test_vm","line":378,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 2cc46799-85eb-4fdb-8807-b8955482fb51, metadata: InstanceMetadata { project_id: e1f269c3-b018-4894-8845-01fa7b05b5c9, silo_id: 9645d99b-01eb-414c-a016-ef7213d20657, sled_id: 6867e2b1-a3a5-483d-b347-48ff3f765c89, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"6867e2b1-a3a5-483d-b347-48ff3f765c89\" }, name: \"phd-vm-2cc46799-85eb-4fdb-8807-b8955482fb51\" }, state: Migrating }","source":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2812025-01-08T21:32:02.130Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.803916673Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","elapsed_milliseconds":493,"source":"migration_from_base_and_back_lifecycle_1","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2822025-01-08T21:32:02.130Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:01.803972865Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","migration_id":"11108d78-190b-4a34-9541-3262ceab4e2d","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2832025-01-08T21:32:04.610Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:04.308790331Z","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}}"}
2842025-01-08T21:32:05.611Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:05.309666384Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2852025-01-08T21:32:05.611Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:05.309724875Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","migration_id":"11108d78-190b-4a34-9541-3262ceab4e2d","elapsed_milliseconds":3505,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2862025-01-08T21:32:05.635Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:05.309774647Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","source":"migration_from_base_and_back_lifecycle_1","elapsed_milliseconds":3999,"path":"phd_tests::migrate::from_base::migration_from_base_and_back","source_id":"65f8fa97-57a3-406a-9356-1251b6404182","target":"migration_from_base_and_back_lifecycle_2","target_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2872025-01-08T21:32:05.635Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:05.310954596Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2882025-01-08T21:32:05.635Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:05.31112935Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2892025-01-08T21:32:05.635Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:05.311176992Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2902025-01-08T21:32:05.635Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:05.311959021Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182"}
2912025-01-08T21:32:05.731Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:05.429599826Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"65f8fa97-57a3-406a-9356-1251b6404182","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":118}
2922025-01-08T21:32:08.461Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.15993577Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":2848}
2932025-01-08T21:32:08.486Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.160238708Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2942025-01-08T21:32:08.486Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.1603315Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2952025-01-08T21:32:08.509Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.193233461Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
2962025-01-08T21:32:08.509Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.193370054Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
2972025-01-08T21:32:08.509Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.193683782Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2982025-01-08T21:32:08.509Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.193761334Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
2992025-01-08T21:32:08.509Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.193885747Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3002025-01-08T21:32:08.509Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.193919728Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":22929}
3012025-01-08T21:32:08.509Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.194961914Z","target":"phd_framework::test_vm","line":1018,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
3022025-01-08T21:32:08.854Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.552231898Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
3032025-01-08T21:32:09.143Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.67015536Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
3042025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.670259583Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-91738afe-25af-4871-9715-679a6bf257aa\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
3052025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.702764294Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
3062025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.702817326Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-3ee913e6-d0a8-4e77-a2a1-9d76c17023af\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51"}
3072025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.727011479Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"2cc46799-85eb-4fdb-8807-b8955482fb51","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":533}
3082025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.72706532Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":91649}
3092025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.727325507Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":533}
3102025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.727401829Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3112025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.72743341Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3122025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.72746003Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3132025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.727682526Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
3142025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.727765978Z","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"}
3152025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.727811939Z","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"}
3162025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.727861331Z","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"}
3172025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.727906101Z","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"}
3182025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.745785558Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 683M 1.80T 682M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
3192025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.74586635Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-9234d0ad-eded-4b21-bb73-005dddcdb369\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::serial_history"}
3202025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.76910292Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-9234d0ad-eded-4b21-bb73-005dddcdb369\", \"phd-artifacts/phd-clone-699eaf4a-1eab-41d7-8c13-79cc22718b22\"]","verb":"clone","path":"phd_tests::migrate::from_base::serial_history"}
3212025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.793778995Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-699eaf4a-1eab-41d7-8c13-79cc22718b22\"]","verb":"list","path":"phd_tests::migrate::from_base::serial_history"}
3222025-01-08T21:32:09.189Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.810509393Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-699eaf4a-1eab-41d7-8c13-79cc22718b22 0B 1.80T 682M /phd-artifacts/phd-clone-699eaf4a-1eab-41d7-8c13-79cc22718b22\n","path":"phd_tests::migrate::from_base::serial_history"}
3232025-01-08T21:32:09.190Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.811135058Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3242025-01-08T21:32:09.190Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.81118443Z","target":"phd_framework::test_vm","line":210,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_serial_history_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","path":"phd_tests::migrate::from_base::serial_history"}
3252025-01-08T21:32:09.190Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.811239581Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/f666d8a901a758714220e83a563f3beddc3a14eca1768ca350a9feca05687ef4/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
3262025-01-08T21:32:09.190Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.811292722Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/f666d8a901a758714220e83a563f3beddc3a14eca1768ca350a9feca05687ef4/propolis-server\"","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
3272025-01-08T21:32:09.190Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.811334413Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stderr_path":"\"/tmp/propolis-phd/migration_serial_history_base.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_serial_history_base.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
3282025-01-08T21:32:09.190Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 881","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.822355628Z","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"}
3292025-01-08T21:32:09.190Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.822629525Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":11}
3302025-01-08T21:32:09.190Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.822746108Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3312025-01-08T21:32:09.190Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:08.823419255Z","target":"phd_framework::test_vm","line":319,"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":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3322025-01-08T21:32:09.501Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.199520298Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3332025-01-08T21:32:09.525Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.199885507Z","target":"phd_framework::test_vm","line":378,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: c8baa7c2-d344-4fb5-8a6a-3daee159af0a, metadata: InstanceMetadata { project_id: 42048adc-94b6-447b-8e39-a4e884555ab1, silo_id: bdb8d112-e974-4287-99f1-ae2738396994, sled_id: 78d2b0c0-26d2-4e5f-8156-b1d8c14a3c1f, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"78d2b0c0-26d2-4e5f-8156-b1d8c14a3c1f\" }, name: \"phd-vm-c8baa7c2-d344-4fb5-8a6a-3daee159af0a\" }, state: Creating }","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3342025-01-08T21:32:09.525Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.199963609Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":377,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3352025-01-08T21:32:09.525Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.200032841Z","target":"phd_framework::test_vm","line":439,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3362025-01-08T21:32:09.525Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.200069582Z","target":"phd_framework::test_vm","line":444,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3372025-01-08T21:32:09.525Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.200595685Z","target":"phd_framework::test_vm","line":439,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3382025-01-08T21:32:09.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.200654736Z","target":"phd_framework::test_vm","line":723,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3392025-01-08T21:32:09.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.200695037Z","target":"phd_framework::test_vm","line":672,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","timeout_duration":"300s","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history"}
3402025-01-08T21:32:09.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.200726128Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
3412025-01-08T21:32:09.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.200756829Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3422025-01-08T21:32:09.526Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:09.2007895Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3432025-01-08T21:32:13.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.441011935Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":4240,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3442025-01-08T21:32:13.743Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.441081107Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
3452025-01-08T21:32:13.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.441244011Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3462025-01-08T21:32:13.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.441289222Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3472025-01-08T21:32:13.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.441323023Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3482025-01-08T21:32:13.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.461067626Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":19,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3492025-01-08T21:32:13.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.461202069Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3502025-01-08T21:32:13.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.461514427Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3512025-01-08T21:32:13.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.461565428Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3522025-01-08T21:32:13.767Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.461604159Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3532025-01-08T21:32:13.796Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.494153111Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3542025-01-08T21:32:13.819Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.494241543Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3552025-01-08T21:32:13.819Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.494302745Z","target":"phd_framework::test_vm","line":723,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4293}
3562025-01-08T21:32:13.819Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.494544661Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3572025-01-08T21:32:13.820Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.494627313Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3582025-01-08T21:32:13.820Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.5049088Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3592025-01-08T21:32:13.820Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.505209047Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3602025-01-08T21:32:13.820Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.505296869Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3612025-01-08T21:32:13.844Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.538027176Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3622025-01-08T21:32:13.867Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.543174755Z","target":"phd_framework::lifecycle","line":74,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3632025-01-08T21:32:13.867Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.543249546Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3642025-01-08T21:32:13.867Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.543297058Z","target":"phd_framework::test_vm","line":210,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","vm_name":"migration_serial_history_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::serial_history"}
3652025-01-08T21:32:13.867Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.543351009Z","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"}
3662025-01-08T21:32:13.867Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.54339652Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::serial_history"}
3672025-01-08T21:32:13.867Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.543434351Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stderr_path":"\"/tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::serial_history"}
3682025-01-08T21:32:13.868Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 882","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.559463201Z","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"}
3692025-01-08T21:32:13.868Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.559765689Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":16}
3702025-01-08T21:32:13.868Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.559909072Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3712025-01-08T21:32:13.868Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.560000764Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"b2493ee8-d69d-459b-8e5b-06f5263b7fd6","timeout_duration":"45s","target_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3722025-01-08T21:32:13.868Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.560099987Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3732025-01-08T21:32:13.868Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.560500097Z","target":"phd_framework::test_vm","line":319,"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_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3742025-01-08T21:32:14.248Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.947036971Z","target":"phd_framework::test_vm","line":378,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 32842b13-b8aa-49d4-8209-1b3005d12c2b, metadata: InstanceMetadata { project_id: 42048adc-94b6-447b-8e39-a4e884555ab1, silo_id: bdb8d112-e974-4287-99f1-ae2738396994, sled_id: eb1f08fd-9660-44bf-9407-a497421ec213, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"eb1f08fd-9660-44bf-9407-a497421ec213\" }, name: \"phd-vm-32842b13-b8aa-49d4-8209-1b3005d12c2b\" }, state: Migrating }","target_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3752025-01-08T21:32:14.272Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.947144434Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","elapsed_milliseconds":387,"source":"migration_serial_history_base","vm":"migration_serial_history_base_lifecycle_0"}
3762025-01-08T21:32:14.272Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:13.947195565Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","migration_id":"b2493ee8-d69d-459b-8e5b-06f5263b7fd6","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3772025-01-08T21:32:16.726Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.423763376Z","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}}"}
3782025-01-08T21:32:16.927Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.625369096Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3792025-01-08T21:32:16.952Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.625473699Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","migration_id":"b2493ee8-d69d-459b-8e5b-06f5263b7fd6","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":2678,"target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3802025-01-08T21:32:16.952Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.62552814Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","elapsed_milliseconds":3065,"path":"phd_tests::migrate::from_base::serial_history","target":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","source_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3812025-01-08T21:32:16.952Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.626788732Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3822025-01-08T21:32:16.952Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.627829508Z","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":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base"}
3832025-01-08T21:32:17.062Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.760552279Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","elapsed_milliseconds":133,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"c8baa7c2-d344-4fb5-8a6a-3daee159af0a"}
3842025-01-08T21:32:17.086Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.762944179Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3852025-01-08T21:32:17.086Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.763143954Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3862025-01-08T21:32:17.086Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.763214196Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3872025-01-08T21:32:17.086Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.763282367Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":7563}
3882025-01-08T21:32:17.086Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.763281557Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3892025-01-08T21:32:17.086Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:16.764294443Z","target":"phd_framework::test_vm","line":1018,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3902025-01-08T21:32:17.732Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.426129335Z","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":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3912025-01-08T21:32:17.866Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.564388845Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3922025-01-08T21:32:17.890Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.564489027Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-699eaf4a-1eab-41d7-8c13-79cc22718b22\"]","verb":"destroy","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3932025-01-08T21:32:17.913Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.598403454Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3942025-01-08T21:32:17.913Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.598467095Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-9234d0ad-eded-4b21-bb73-005dddcdb369\"]","verb":"destroy","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b","path":"phd_tests::migrate::from_base::serial_history","vm":"migration_serial_history_base_lifecycle_0"}
3952025-01-08T21:32:17.937Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.623943291Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","elapsed_milliseconds":860,"path":"phd_tests::migrate::from_base::serial_history","vm_id":"32842b13-b8aa-49d4-8209-1b3005d12c2b"}
3962025-01-08T21:32:17.937Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.623995202Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":8896}
3972025-01-08T21:32:17.937Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.624274379Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":860}
3982025-01-08T21:32:17.937Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.624342121Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3992025-01-08T21:32:17.937Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.624374331Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
4002025-01-08T21:32:17.937Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.624401832Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4012025-01-08T21:32:17.937Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.624596897Z","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"}
4022025-01-08T21:32:17.937Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.624681629Z","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"}
4032025-01-08T21:32:17.937Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.62472377Z","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"}
4042025-01-08T21:32:17.938Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.624769431Z","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"}
4052025-01-08T21:32:17.938Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.624820973Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4062025-01-08T21:32:17.961Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.643341475Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 683M 1.80T 682M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4072025-01-08T21:32:17.961Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.643480618Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-abae31f1-4085-4724-8da4-3f50b9cf6ab4\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4082025-01-08T21:32:17.985Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.668132353Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-abae31f1-4085-4724-8da4-3f50b9cf6ab4\", \"phd-artifacts/phd-clone-a36bf677-4271-4fcf-98ab-61df18457b6a\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4092025-01-08T21:32:18.008Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.6912332Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-a36bf677-4271-4fcf-98ab-61df18457b6a\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4102025-01-08T21:32:18.032Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.707896815Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-a36bf677-4271-4fcf-98ab-61df18457b6a 0B 1.80T 682M /phd-artifacts/phd-clone-a36bf677-4271-4fcf-98ab-61df18457b6a\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4112025-01-08T21:32:18.032Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.708509301Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4122025-01-08T21:32:18.032Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.708559322Z","target":"phd_framework::test_vm","line":210,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4132025-01-08T21:32:18.033Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.708609043Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/f666d8a901a758714220e83a563f3beddc3a14eca1768ca350a9feca05687ef4/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4142025-01-08T21:32:18.033Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.708660605Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/f666d8a901a758714220e83a563f3beddc3a14eca1768ca350a9feca05687ef4/propolis-server\"","bootrom_path":"\"/phd-artifacts/29813374b58e3b77fb665f2d95cb3bab37d44fdd2c4fce2a70de9d76a3512a4f/OVMF_CODE.fd\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4152025-01-08T21:32:18.033Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.708702535Z","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.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4162025-01-08T21:32:18.033Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 891","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.719252269Z","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"}
4172025-01-08T21:32:18.033Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.719528036Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10}
4182025-01-08T21:32:18.033Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.719646219Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4192025-01-08T21:32:18.033Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:17.720342406Z","target":"phd_framework::test_vm","line":319,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4202025-01-08T21:32:18.879Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.578125848Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
4212025-01-08T21:32:18.925Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.578497668Z","target":"phd_framework::test_vm","line":378,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 1afdae08-2851-4cd4-b4bb-292ce29508f4, metadata: InstanceMetadata { project_id: f93d6a06-36d1-4c5d-a831-f6c2f37956c1, silo_id: c88a6a45-3c8e-4692-a394-0d13faa99db8, sled_id: 3cd88892-8405-48db-a8e7-28453f8c5d3d, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"3cd88892-8405-48db-a8e7-28453f8c5d3d\" }, name: \"phd-vm-1afdae08-2851-4cd4-b4bb-292ce29508f4\" }, state: Creating }","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4222025-01-08T21:32:18.925Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.578556439Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":858,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4232025-01-08T21:32:18.925Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.57860029Z","target":"phd_framework::test_vm","line":439,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4242025-01-08T21:32:18.925Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.578633841Z","target":"phd_framework::test_vm","line":444,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4252025-01-08T21:32:18.925Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.579178235Z","target":"phd_framework::test_vm","line":439,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":0,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4262025-01-08T21:32:18.925Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.579232486Z","target":"phd_framework::test_vm","line":723,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4272025-01-08T21:32:18.925Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.579272197Z","target":"phd_framework::test_vm","line":672,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","timeout_duration":"300s","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4282025-01-08T21:32:18.926Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.579303208Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4292025-01-08T21:32:18.926Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.579333279Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4302025-01-08T21:32:18.926Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:18.57936575Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4312025-01-08T21:32:23.077Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.774772576Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":4195,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4322025-01-08T21:32:23.077Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.774847738Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4332025-01-08T21:32:23.101Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.775015332Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4342025-01-08T21:32:23.101Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.775063413Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4352025-01-08T21:32:23.101Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.775096414Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4362025-01-08T21:32:23.101Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.793943194Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":18,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4372025-01-08T21:32:23.101Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.794072478Z","target":"phd_framework::test_vm","line":680,"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"}
4382025-01-08T21:32:23.101Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.794406246Z","target":"phd_framework::test_vm","line":680,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4392025-01-08T21:32:23.101Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.794467507Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4402025-01-08T21:32:23.101Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.794509168Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4412025-01-08T21:32:23.128Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.827059221Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4422025-01-08T21:32:23.152Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.827158553Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4432025-01-08T21:32:23.152Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.827221025Z","target":"phd_framework::test_vm","line":723,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4247}
4442025-01-08T21:32:23.152Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.827414789Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4452025-01-08T21:32:23.152Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.82745629Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4462025-01-08T21:32:23.152Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.837802439Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4472025-01-08T21:32:23.152Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.838017444Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4482025-01-08T21:32:23.153Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.838093296Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4492025-01-08T21:32:23.177Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.860434553Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":22,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4502025-01-08T21:32:23.177Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.860567567Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4512025-01-08T21:32:23.177Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.860614868Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4522025-01-08T21:32:23.177Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.871057049Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4532025-01-08T21:32:23.177Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.871272504Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4542025-01-08T21:32:23.177Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.871353296Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4552025-01-08T21:32:23.205Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.904025261Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4562025-01-08T21:32:23.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.904246446Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4572025-01-08T21:32:23.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.904323799Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4582025-01-08T21:32:23.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.91480689Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4592025-01-08T21:32:23.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.915101648Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4602025-01-08T21:32:23.229Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.91519045Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4612025-01-08T21:32:23.253Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.947813654Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4622025-01-08T21:32:23.253Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.947934537Z","target":"phd_framework::lifecycle","line":74,"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"}
4632025-01-08T21:32:23.253Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.948043909Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4642025-01-08T21:32:23.253Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.948124421Z","target":"phd_framework::test_vm","line":210,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4652025-01-08T21:32:23.253Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.948218824Z","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"}
4662025-01-08T21:32:23.253Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.948297076Z","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::can_migrate_from_base"}
4672025-01-08T21:32:23.253Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.948380748Z","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"}
4682025-01-08T21:32:23.276Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 892","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.962723325Z","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"}
4692025-01-08T21:32:23.277Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.962920029Z","target":"phd_framework::test_vm","line":192,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":14}
4702025-01-08T21:32:23.277Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.963009552Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","target_id":"46008a92-2a35-46a7-9223-ec350e780550","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4712025-01-08T21:32:23.277Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.963065433Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"d59f7d5c-0289-4393-b6ac-64a86e59b820","timeout_duration":"45s","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","target_id":"46008a92-2a35-46a7-9223-ec350e780550","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4722025-01-08T21:32:23.277Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.963141215Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550","target_id":"46008a92-2a35-46a7-9223-ec350e780550","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4732025-01-08T21:32:23.277Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:22.963603807Z","target":"phd_framework::test_vm","line":319,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance)","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550","target_id":"46008a92-2a35-46a7-9223-ec350e780550","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4742025-01-08T21:32:23.802Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:23.50080258Z","target":"phd_framework::test_vm","line":378,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 46008a92-2a35-46a7-9223-ec350e780550, metadata: InstanceMetadata { project_id: f93d6a06-36d1-4c5d-a831-f6c2f37956c1, silo_id: c88a6a45-3c8e-4692-a394-0d13faa99db8, sled_id: 9a7142ac-241d-4f4f-ac68-e211820f529a, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"9a7142ac-241d-4f4f-ac68-e211820f529a\" }, name: \"phd-vm-46008a92-2a35-46a7-9223-ec350e780550\" }, state: Migrating }","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550","target_id":"46008a92-2a35-46a7-9223-ec350e780550","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4752025-01-08T21:32:23.826Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:23.500905843Z","target":"phd_framework::test_vm","line":275,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":537,"path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550","target_id":"46008a92-2a35-46a7-9223-ec350e780550","source":"migration_from_base"}
4762025-01-08T21:32:23.826Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:23.500955674Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","migration_id":"d59f7d5c-0289-4393-b6ac-64a86e59b820","target_id":"46008a92-2a35-46a7-9223-ec350e780550","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4772025-01-08T21:32:26.274Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:25.972661544Z","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}}"}
4782025-01-08T21:32:26.361Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:26.059135842Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","target_id":"46008a92-2a35-46a7-9223-ec350e780550","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4792025-01-08T21:32:26.361Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:26.059181703Z","target":"phd_framework::test_vm","line":527,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","migration_id":"d59f7d5c-0289-4393-b6ac-64a86e59b820","elapsed_milliseconds":2558,"target_id":"46008a92-2a35-46a7-9223-ec350e780550","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4802025-01-08T21:32:26.384Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:26.059225114Z","target":"phd_framework::test_vm","line":473,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":3096,"target_id":"46008a92-2a35-46a7-9223-ec350e780550","path":"phd_tests::migrate::from_base::can_migrate_from_base","source":"migration_from_base","target":"migration_from_base_lifecycle_0"}
4812025-01-08T21:32:26.384Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:26.060386413Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4822025-01-08T21:32:26.384Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:26.060581208Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
4832025-01-08T21:32:26.384Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:26.060627109Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
4842025-01-08T21:32:26.384Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:26.061379648Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4"}
4852025-01-08T21:32:26.493Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:26.192017288Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"1afdae08-2851-4cd4-b4bb-292ce29508f4","elapsed_milliseconds":131,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4862025-01-08T21:32:29.722Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.419755021Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550","elapsed_milliseconds":3359,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4872025-01-08T21:32:29.746Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.420044358Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
4882025-01-08T21:32:29.746Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.42013606Z","target":"phd_framework::test_vm","line":745,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
4892025-01-08T21:32:29.770Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.452904858Z","target":"phd_framework::test_vm","line":738,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550","elapsed_milliseconds":32,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4902025-01-08T21:32:29.770Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.453074022Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
4912025-01-08T21:32:29.770Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.453312428Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
4922025-01-08T21:32:29.770Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.453488853Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":10875}
4932025-01-08T21:32:29.770Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.453485283Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
4942025-01-08T21:32:29.770Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.453607966Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
4952025-01-08T21:32:29.770Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.454539239Z","target":"phd_framework::test_vm","line":1018,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
4962025-01-08T21:32:30.193Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:29.891459991Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
4972025-01-08T21:32:30.307Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.006117101Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
4982025-01-08T21:32:30.331Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.006181623Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-a36bf677-4271-4fcf-98ab-61df18457b6a\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
4992025-01-08T21:32:30.354Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.041136175Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
5002025-01-08T21:32:30.354Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.041188356Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-abae31f1-4085-4724-8da4-3f50b9cf6ab4\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550"}
5012025-01-08T21:32:30.378Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.066370825Z","target":"phd_framework::test_vm","line":995,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","vm_id":"46008a92-2a35-46a7-9223-ec350e780550","elapsed_milliseconds":613,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
5022025-01-08T21:32:30.378Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.066426966Z","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":12441}
5032025-01-08T21:32:30.378Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.066627371Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":612}
5042025-01-08T21:32:30.378Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.066697523Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5052025-01-08T21:32:30.378Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.066727424Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5062025-01-08T21:32:30.378Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 112.99s
5072025-01-08T21:32:30.378Z
5082025-01-08T21:32:30.378Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"buskin","pid":862,"time":"2025-01-08T21:32:30.066794635Z","target":"phd_runner","line":40,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5092025-01-08T21:32:30.425Z
5102025-01-08T21:32:30.449Zreal 1:53.699285477
5112025-01-08T21:32:30.449Zuser 36.616037555
5122025-01-08T21:32:30.449Zsys 15.362998436
5132025-01-08T21:32:30.449Ztrap 0.003919282
5142025-01-08T21:32:30.449Ztflt 0.001508171
5152025-01-08T21:32:30.449Zdflt 0.000362529
5162025-01-08T21:32:30.449Zkflt 0.000278641
5172025-01-08T21:32:30.449Zlock 1:51:27.329345434
5182025-01-08T21:32:30.449Zslp 4:52.666819484
5192025-01-08T21:32:30.449Zlat 0.348297054
5202025-01-08T21:32:30.449Zstop 15.925446358
5212025-01-08T21:32:30.449Z+ failcount=0
5222025-01-08T21:32:30.449Z+ set -e
5232025-01-08T21:32:30.449Z+ 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
5242025-01-08T21:32:30.449ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5252025-01-08T21:32:30.449Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5262025-01-08T21:32:30.449Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log 204K
5272025-01-08T21:32:30.449Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5282025-01-08T21:32:30.449Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log 204K
5292025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5302025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log 116K
5312025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base_and_back.serial.log 7K
5322025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base_and_back.stderr.log 0K
5332025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base_and_back.stdout.log 115K
5342025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log 0K
5352025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log 116K
5362025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base.serial.log 7K
5372025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base.stderr.log 0K
5382025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_from_base.stdout.log 115K
5392025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log 0K
5402025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log 116K
5412025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_serial_history_base.serial.log 7K
5422025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_serial_history_base.stderr.log 0K
5432025-01-08T21:32:30.450Za /tmp/propolis-phd/migration_serial_history_base.stdout.log 116K
5442025-01-08T21:32:30.450Z+ exitcode=0
5452025-01-08T21:32:30.450Z+ '[' 0 -eq 0 ']'
5462025-01-08T21:32:30.450Z+ echo
5472025-01-08T21:32:30.450Z
5482025-01-08T21:32:30.450Z+ echo 'ALL TESTS PASSED'
5492025-01-08T21:32:30.450ZALL TESTS PASSED
5502025-01-08T21:32:30.450Z
5512025-01-08T21:32:30.450Z+ echo
5522025-01-08T21:32:30.450Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5532025-01-08T21:32:30.450Z+ read
5542025-01-08T21:32:30.450Z+ exit 0
5552025-01-08T21:32:30.450Zprocess exited: duration 122977 ms, exit code 0
 
5562025-01-08T21:32:30.525Zfound 2 output files
5572025-01-08T21:32:30.525Zuploading: /tmp/phd-runner.log (163539 bytes)
5582025-01-08T21:32:31.684Zuploaded: /tmp/phd-runner.log
5592025-01-08T21:32:31.684Zuploading: /tmp/phd-tmp-files.tar.gz (86752 bytes)
5602025-01-08T21:32:32.888Zuploaded: /tmp/phd-tmp-files.tar.gz