01J835JRSKNBJQ26T037KFPE5G: 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: 01J835K1PTACTW4KYRZW6YGCKV

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12024-09-18T18:25:22.172Zjob dependencies complete; ready to run (waiting for 8 m 58 s)
22024-09-18T18:26:12.353Zjob assigned to worker 01J8363P5GNATHFKVV2C599683 (queued for 50 s)
32024-09-18T18:26:12.629Zhttp://172.20.0.5:9969/ipxe/buskin... ok
42024-09-18T18:26:12.675Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/kernel/amd64/unix... ok
52024-09-18T18:26:12.712Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive... ok
62024-09-18T18:26:12.745Zhttp://172.20.0.5:9969/os/buskin/platform/i86pc/amd64/boot_archive.hash... ok
72024-09-18T18:26:12.778Zhttp://172.20.0.5:9969/postboot/buskin... ok
82024-09-18T18:26:12.812ZwcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U
92024-09-18T18:26:12.848Zcpu0: microcode has been updated from version 0xa001133 to 0xa0011d5
102024-09-18T18:26:12.879ZOxide Helios Version helios-2.0.22827 64-bit
112024-09-18T18:26:12.913ZConfiguring devices.
122024-09-18T18:26:12.946Z##################################################
132024-09-18T18:26:12.981Z#### ############# ##
142024-09-18T18:26:13.013Z### ### ############ ##
152024-09-18T18:26:13.047Z## ### # ## ### ## Oxide Computer Company ##
162024-09-18T18:26:13.080Z## ## ## ### # ### ##
172024-09-18T18:26:13.113Z## # ### #### #### This Station Under ##
182024-09-18T18:26:13.147Z### ### #### # ### Computer Control ##
192024-09-18T18:26:13.180Z#### #### ### ## ##
202024-09-18T18:26:13.219Z##################################################
212024-09-18T18:26:13.258ZHostname: buskin
222024-09-18T18:26:13.292ZLoading smf(7) service descriptions:
232024-09-18T18:26:13.501Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
242024-09-18T18:26:13.525Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
252024-09-18T18:26:13.525Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
262024-09-18T18:26:13.553Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
272024-09-18T18:26:13.553Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
282024-09-18T18:26:26.692Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
292024-09-18T18:26:26.692Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
302024-09-18T18:26:26.728Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
312024-09-18T18:26:26.753Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
322024-09-18T18:26:51.333Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
332024-09-18T18:26:51.357Zstarting task 0: "setup"
342024-09-18T18:26:51.357Z++ uname -s
352024-09-18T18:26:51.357Z+ kern=SunOS
362024-09-18T18:26:51.357Z+ case "$kern" in
372024-09-18T18:26:51.357Z+ groupadd -g 12345 build
382024-09-18T18:26:51.357Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
392024-09-18T18:26:53.352Z+ zfs create -o mountpoint=/work rpool/work
402024-09-18T18:26:53.377Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
412024-09-18T18:26:53.377Z+ home_fs=zfs
422024-09-18T18:26:53.377Z+ [[ zfs == autofs ]]
432024-09-18T18:26:53.377Z+ mkdir -p /home/build
442024-09-18T18:26:53.377Z+ chown build:build /home/build /work
452024-09-18T18:26:55.378Z+ chmod 0700 /home/build /work
462024-09-18T18:26:55.402Zprocess exited: duration 4048 ms, exit code 0
 
472024-09-18T18:26:55.449Zstarting task 1: "authentication"
482024-09-18T18:26:55.493Zprocess exited: duration 43 ms, exit code 0
 
492024-09-18T18:26:55.542Zstarting task 2: "build"
502024-09-18T18:26:55.566Z+ indir=/input
512024-09-18T18:26:55.566Z+ indir_suffix='phd-build/out/*.tar.gz'
522024-09-18T18:26:55.566Z+ phddir=/work/phd-test
532024-09-18T18:26:55.566Z+ pfexec zpool create -f phd-artifacts c1t1d0 c2t1d0
542024-09-18T18:26:55.689Z+ artifactdir=/phd-artifacts
552024-09-18T18:26:55.689Z+ banner Inputs
562024-09-18T18:26:55.714Z ###
572024-09-18T18:26:55.714Z # # # ##### # # ##### ####
582024-09-18T18:26:55.714Z # ## # # # # # # #
592024-09-18T18:26:55.714Z # # # # # # # # # ####
602024-09-18T18:26:55.714Z # # # # ##### # # # #
612024-09-18T18:26:55.714Z # # ## # # # # # #
622024-09-18T18:26:55.714Z ### # # # #### # ####
632024-09-18T18:26:55.714Z
642024-09-18T18:26:55.714Z+ find /input -ls
652024-09-18T18:26:55.714Z 34 1 drwxr-xr-x 3 root root 3 Sep 18 18:26 /input
662024-09-18T18:26:55.714Z 2 1 drwxr-xr-x 3 root root 3 Sep 18 18:26 /input/phd-build
672024-09-18T18:26:55.714Z 3 2 drwxr-xr-x 2 root root 7 Sep 18 18:26 /input/phd-build/out
682024-09-18T18:26:55.714Z 130 72929 -rw-r--r-- 1 root root 74630400 Sep 18 18:26 /input/phd-build/out/phd-runner.tar.gz
692024-09-18T18:26:55.714Z 129 1 -rw-r--r-- 1 root root 65 Sep 18 18:26 /input/phd-build/out/phd-runner.sha256.txt
702024-09-18T18:26:55.714Z 257 139078 -rw-r--r-- 1 root root 142323010 Sep 18 18:26 /input/phd-build/out/propolis-server-debug.tar.gz
712024-09-18T18:26:55.714Z 256 1 -rw-r--r-- 1 root root 65 Sep 18 18:26 /input/phd-build/out/propolis-server-debug.sha256.txt
722024-09-18T18:26:55.714Z 128 2 -rw-r--r-- 1 root root 1795 Sep 18 18:26 /input/phd-build/out/phd-run-with-args.sh
732024-09-18T18:26:55.714Z+ rm -rf /work/phd-test
742024-09-18T18:26:55.714Z+ mkdir /work/phd-test
752024-09-18T18:26:55.714Z+ for p in $indir/$indir_suffix
762024-09-18T18:26:55.714Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
772024-09-18T18:26:57.349ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
782024-09-18T18:26:57.349Zx phd-runner, 271385640 bytes, 530051 tape blocks
792024-09-18T18:26:57.349Zx artifacts.toml, 548 bytes, 2 tape blocks
802024-09-18T18:26:57.374Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
812024-09-18T18:26:58.940Z+ for f in $(tar tf "$p")
822024-09-18T18:26:58.940Z+ chmod +x /work/phd-test/phd-runner
832024-09-18T18:26:58.965Z+ for f in $(tar tf "$p")
842024-09-18T18:26:58.965Z+ chmod +x /work/phd-test/artifacts.toml
852024-09-18T18:26:58.965Z+ for p in $indir/$indir_suffix
862024-09-18T18:26:58.965Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
872024-09-18T18:27:02.249ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
882024-09-18T18:27:02.249Zx propolis-server, 550746968 bytes, 1075678 tape blocks
892024-09-18T18:27:02.274Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
902024-09-18T18:27:05.276Z+ for f in $(tar tf "$p")
912024-09-18T18:27:05.276Z+ chmod +x /work/phd-test/propolis-server
922024-09-18T18:27:05.300Z+ ls /work/phd-test
932024-09-18T18:27:05.300Zartifacts.toml
942024-09-18T18:27:05.300Zphd-runner
952024-09-18T18:27:05.300Zpropolis-server
962024-09-18T18:27:05.300Z+ banner Setup
972024-09-18T18:27:05.300Z #####
982024-09-18T18:27:05.300Z# # ###### ##### # # #####
992024-09-18T18:27:05.300Z# # # # # # #
1002024-09-18T18:27:05.300Z ##### ##### # # # # #
1012024-09-18T18:27:05.300Z # # # # # #####
1022024-09-18T18:27:05.300Z# # # # # # #
1032024-09-18T18:27:05.300Z ##### ###### # #### #
1042024-09-18T18:27:05.300Z
1052024-09-18T18:27:05.300Z+ tmpdir=/tmp/propolis-phd
1062024-09-18T18:27:05.300Z+ '[' '!' -d /tmp/propolis-phd ']'
1072024-09-18T18:27:05.300Z+ mkdir /tmp/propolis-phd
1082024-09-18T18:27:05.300Z+ banner Tests
1092024-09-18T18:27:05.300Z#######
1102024-09-18T18:27:05.300Z # ###### #### ##### ####
1112024-09-18T18:27:05.300Z # # # # #
1122024-09-18T18:27:05.300Z # ##### #### # ####
1132024-09-18T18:27:05.301Z # # # # #
1142024-09-18T18:27:05.301Z # # # # # # #
1152024-09-18T18:27:05.301Z # ###### #### # ####
1162024-09-18T18:27:05.301Z
1172024-09-18T18:27:05.301Z+ runner=/work/phd-test/phd-runner
1182024-09-18T18:27:05.301Z+ artifacts=/work/phd-test/artifacts.toml
1192024-09-18T18:27:05.301Z+ propolis=/work/phd-test/propolis-server
1202024-09-18T18:27:05.301Z+ ls /work/phd-test/phd-runner
1212024-09-18T18:27:05.301Z/work/phd-test/phd-runner
1222024-09-18T18:27:05.301Z+ ls /work/phd-test/artifacts.toml
1232024-09-18T18:27:05.301Z/work/phd-test/artifacts.toml
1242024-09-18T18:27:05.301Z+ ls /work/phd-test/propolis-server
1252024-09-18T18:27:05.301Z/work/phd-test/propolis-server
1262024-09-18T18:27:05.301Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1272024-09-18T18:27:05.301Z+ set +e
1282024-09-18T18:27:05.301Z+ RUST_BACKTRACE=1
1292024-09-18T18:27:05.301Z+ RUST_LOG=info,phd=debug
1302024-09-18T18:27:05.301Z+ 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
1312024-09-18T18:27:05.301Z+ tee /tmp/phd-runner.log
1322024-09-18T18:27:05.325Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:05.649447839Z","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 }"}
1332024-09-18T18:27:05.349Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:05.651685973Z","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: 1352, tv_nsec: 172361286 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1342024-09-18T18:27:05.349Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:05.651745074Z","target":"phd_framework::artifacts::store","line":229,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1352024-09-18T18:27:05.349Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:05.651827065Z","target":"phd_framework::artifacts::store","line":313,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"9d82a99058e7f4d76ccc2141dcd78e7d4730cc78"}
1362024-09-18T18:27:05.349Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:05.652045579Z","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/9d82a99058e7f4d76ccc2141dcd78e7d4730cc78/crucible-nightly.sha256.txt"}
1372024-09-18T18:27:05.460Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:05.785377361Z","target":"phd_framework::artifacts::store","line":250,"file":"phd-tests/framework/src/artifacts/store.rs"}
1382024-09-18T18:27:05.914Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.239067576Z","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/a9c5fdac442fa6fd5a65e413ea874fe3c62c3fd9/propolis-server.sha256.txt"}
1392024-09-18T18:27:06.031Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.355766622Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1402024-09-18T18:27:06.058Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.355928815Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1412024-09-18T18:27:06.058Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.356099038Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1422024-09-18T18:27:06.058Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.356187539Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1432024-09-18T18:27:06.058Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.356224319Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1442024-09-18T18:27:06.058Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.35626144Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1452024-09-18T18:27:06.058Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.356423812Z","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"}
1462024-09-18T18:27:06.059Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.356671216Z","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"}
1472024-09-18T18:27:06.059Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:06.356806918Z","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"}
1482024-09-18T18:27:06.687Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:07.012123387Z","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"}
1492024-09-18T18:27:06.711Z{"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":860,"time":"2024-09-18T18:27:07.012395561Z","target":"phd_framework::artifacts::store","line":618,"file":"phd-tests/framework/src/artifacts/store.rs","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1502024-09-18T18:27:34.709Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.033553197Z","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"}
1512024-09-18T18:27:34.733Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.033665138Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1522024-09-18T18:27:34.733Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.056989888Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 2.00M 1.80T 1.91M /phd-artifacts\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1532024-09-18T18:27:34.733Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.057227411Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-454ca2f4-334e-48a4-bdc0-a0eefcaf1c52\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1542024-09-18T18:27:34.784Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.108962528Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-454ca2f4-334e-48a4-bdc0-a0eefcaf1c52\", \"phd-artifacts/phd-clone-6c097792-b380-45c4-99e6-f9ccff525ba7\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1552024-09-18T18:27:34.809Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.128307355Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-6c097792-b380-45c4-99e6-f9ccff525ba7\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1562024-09-18T18:27:34.833Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.138774607Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-6c097792-b380-45c4-99e6-f9ccff525ba7 0B 1.80T 48.9M /phd-artifacts/phd-clone-6c097792-b380-45c4-99e6-f9ccff525ba7\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1572024-09-18T18:27:34.833Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.139803482Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1582024-09-18T18:27:34.833Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.139858473Z","target":"phd_framework::test_vm","line":204,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","vm_name":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1592024-09-18T18:27:34.833Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.139915114Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/2a13bdc8e33c968b5133ba5d408d0849f32970a6b469b9b9f0be0185bc46f271/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1602024-09-18T18:27:34.833Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:35.139971775Z","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/a9c5fdac442fa6fd5a65e413ea874fe3c62c3fd9/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1612024-09-18T18:27:59.073Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:59.397382898Z","target":"phd_framework::artifacts::store","line":162,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/2a13bdc8e33c968b5133ba5d408d0849f32970a6b469b9b9f0be0185bc46f271/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1622024-09-18T18:27:59.073Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:27:59.39749675Z","target":"phd_framework::artifacts::store","line":518,"file":"phd-tests/framework/src/artifacts/store.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1632024-09-18T18:28:12.110Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.434376122Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9000","config_toml_path":"\"/tmp/propolis-phd/migration_from_base_and_back.config.toml\"","server_path":"\"/phd-artifacts/2a13bdc8e33c968b5133ba5d408d0849f32970a6b469b9b9f0be0185bc46f271/propolis-server\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1642024-09-18T18:28:12.134Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.434517985Z","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.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back.stderr.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1652024-09-18T18:28:12.160Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 865","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.484355722Z","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"}
1662024-09-18T18:28:12.184Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.484922511Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":37345}
1672024-09-18T18:28:12.184Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.485164684Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1682024-09-18T18:28:12.184Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.485941967Z","target":"phd_framework::test_vm","line":369,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance/spec): error trying to connect: tcp connect error: Connection refused (os error 146)","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1692024-09-18T18:28:12.693Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.887986066Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1702024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.889150524Z","target":"phd_framework::test_vm","line":428,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { disks: [], nics: [], properties: InstanceProperties { bootrom_id: 00000000-0000-0000-0000-000000000000, description: \"Pheidippides-managed VM\", id: 1ac4585f-0fce-463f-be7c-77197a03c024, image_id: 00000000-0000-0000-0000-000000000000, memory: 512, metadata: InstanceMetadata { project_id: 2a6c8901-3efd-46b0-99c4-cca58d3ce5a6, silo_id: e4b3d3de-6ed8-4575-a530-40565465357e, sled_id: e19ea39c-5220-45af-b402-b29a50b4b191, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"e19ea39c-5220-45af-b402-b29a50b4b191\" }, name: \"phd-vm-1ac4585f-0fce-463f-be7c-77197a03c024\", vcpus: 2 }, state: Creating }","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1712024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.889237465Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":404}
1722024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.889340517Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1732024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.889386967Z","target":"phd_framework::test_vm","line":510,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1742024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.890006487Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":0}
1752024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.890092918Z","target":"phd_framework::test_vm","line":762,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1762024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.890140909Z","target":"phd_framework::test_vm","line":711,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","timeout_duration":"300s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1772024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.89019046Z","target":"phd_framework::test_vm","line":719,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1782024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.890229551Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1792024-09-18T18:28:12.718Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:12.890292872Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1802024-09-18T18:28:16.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.131302472Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4241}
1812024-09-18T18:28:16.810Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.131380453Z","target":"phd_framework::test_vm","line":719,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1822024-09-18T18:28:16.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.131634017Z","target":"phd_framework::test_vm","line":719,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1832024-09-18T18:28:16.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.131685297Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1842024-09-18T18:28:16.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.131722278Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1852024-09-18T18:28:16.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.149802976Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":18}
1862024-09-18T18:28:16.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.149944849Z","target":"phd_framework::test_vm","line":759,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1872024-09-18T18:28:16.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.15001268Z","target":"phd_framework::test_vm","line":762,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4259}
1882024-09-18T18:28:16.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.150355345Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1892024-09-18T18:28:16.835Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.150459286Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1902024-09-18T18:28:16.860Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.160991289Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
1912024-09-18T18:28:16.860Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.161211612Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1922024-09-18T18:28:16.860Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.161285213Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1932024-09-18T18:28:16.860Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.182818915Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":21}
1942024-09-18T18:28:16.860Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.183095219Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1952024-09-18T18:28:16.860Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.18315745Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"touch ./foo.bar","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1962024-09-18T18:28:16.885Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.193647331Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
1972024-09-18T18:28:16.885Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.193868045Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1982024-09-18T18:28:16.885Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.193954576Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
1992024-09-18T18:28:16.909Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.226767591Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":32}
2002024-09-18T18:28:16.909Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.227018755Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2012024-09-18T18:28:16.909Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.227102666Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2022024-09-18T18:28:16.934Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.237478796Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":10}
2032024-09-18T18:28:16.934Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.237684729Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2042024-09-18T18:28:16.934Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.237762841Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2052024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.259364913Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":21}
2062024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.259535486Z","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"}
2072024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.259635477Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2082024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.259706659Z","target":"phd_framework::test_vm","line":204,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2092024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.25980586Z","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"}
2102024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.259887041Z","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"}
2112024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.260001883Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","config_toml_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.config.toml\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2122024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.260074044Z","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"}
2132024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 866","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.279517673Z","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"}
2142024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.27995413Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":20}
2152024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.280060452Z","target":"phd_framework::test_vm","line":539,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"80db91b4-36f2-4be4-9022-5422e94c246a","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"1ac4585f-0fce-463f-be7c-77197a03c024"}
2162024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.280148203Z","target":"phd_framework::test_vm","line":572,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"c8dd732f-1c6c-453f-9d93-64f26ab69d04","timeout_duration":"45s","target_id":"80db91b4-36f2-4be4-9022-5422e94c246a","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"1ac4585f-0fce-463f-be7c-77197a03c024"}
2172024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.280217324Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"80db91b4-36f2-4be4-9022-5422e94c246a","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"80db91b4-36f2-4be4-9022-5422e94c246a","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"1ac4585f-0fce-463f-be7c-77197a03c024"}
2182024-09-18T18:28:16.959Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.280743702Z","target":"phd_framework::test_vm","line":369,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance/spec): error trying to connect: tcp connect error: Connection refused (os error 146)","target_id":"80db91b4-36f2-4be4-9022-5422e94c246a","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"80db91b4-36f2-4be4-9022-5422e94c246a","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"1ac4585f-0fce-463f-be7c-77197a03c024"}
2192024-09-18T18:28:17.531Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] permanent error from instance_spec_ensure","level":50,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.852731838Z","target":"phd_framework::test_vm","line":373,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Error Response: status: 500 Internal Server Error; headers: {\"content-type\": \"application/json\", \"x-request-id\": \"466c2a3b-14c6-4b8c-8502-45906d6ff259\", \"content-length\": \"124\", \"date\": \"Wed, 18 Sep 2024 18:28:17 GMT\"}; value: Error { error_code: Some(\"Internal\"), message: \"Internal Server Error\", request_id: \"466c2a3b-14c6-4b8c-8502-45906d6ff259\" }","target_id":"80db91b4-36f2-4be4-9022-5422e94c246a","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"80db91b4-36f2-4be4-9022-5422e94c246a","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"1ac4585f-0fce-463f-be7c-77197a03c024"}
2202024-09-18T18:28:17.556Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.853771904Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"80db91b4-36f2-4be4-9022-5422e94c246a","target_id":"80db91b4-36f2-4be4-9022-5422e94c246a","source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","elapsed_milliseconds":573,"source_id":"1ac4585f-0fce-463f-be7c-77197a03c024"}
2212024-09-18T18:28:17.556Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.853820885Z","target":"phd_framework::test_vm","line":539,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"80db91b4-36f2-4be4-9022-5422e94c246a","elapsed_milliseconds":573,"source":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","target":"migration_from_base_and_back_lifecycle_0","source_id":"1ac4585f-0fce-463f-be7c-77197a03c024"}
2222024-09-18T18:28:17.556Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.853949187Z","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"}
2232024-09-18T18:28:17.580Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.882023099Z","target":"phd_framework::test_vm","line":1017,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2242024-09-18T18:28:17.580Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.883497542Z","target":"phd_framework::test_vm","line":1040,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2252024-09-18T18:28:17.660Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.984666199Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2262024-09-18T18:28:17.707Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.984843922Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":5096}
2272024-09-18T18:28:17.707Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... FAILED: Error Response: status: 500 Internal Server Error; headers: {\"content-type\": \"application/json\", \"x-request-id\": \"466c2a3b-14c6-4b8c-8502-45906d6ff259\", \"content-length\": \"124\", \"date\": \"Wed, 18 Sep 2024 18:28:17 GMT\"}; value: Error { error_code: Some(\"Internal\"), message: \"Internal Server Error\", request_id: \"466c2a3b-14c6-4b8c-8502-45906d6ff259\" }\n\nStack backtrace:\n 0: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.86/src/backtrace.rs:27:14\n 1: <core::result::Result<T,F> as core::ops::try_trait::FromResidual<core::result::Result<core::convert::Infallible,E>>>::from_residual\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/result.rs:1989:27\n 2: phd_framework::test_vm::TestVm::instance_ensure_internal::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:385:9\n 3: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9\n 4: phd_framework::test_vm::TestVm::instance_ensure_internal::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:290:5\n 5: phd_framework::test_vm::TestVm::migrate_from::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:589:22\n 6: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9\n 7: phd_framework::test_vm::TestVm::migrate_from::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:539:5\n 8: phd_framework::lifecycle::<impl phd_framework::Framework>::lifecycle_test::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/lifecycle.rs:95:26\n 9: phd_tests::migrate::from_base::migration_from_base_and_back::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/tests/src/migrate.rs:83:10\n 10: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9\n 11: phd_tests::migrate::from_base::migration_from_base_and_back::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/tests/src/migrate.rs:52:5\n 12: <core::pin::Pin<P> as core::future::future::Future>::poll\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/future/future.rs:123:9\n 13: phd_testcase::TestCase::run::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/testcase/src/lib.rs:79:32\n 14: phd_runner::execute::run_tests_with_ctx::{{closure}}::{{closure}}::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/macros/select.rs:557:49\n 15: <tokio::future::poll_fn::PollFn<F> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/future/poll_fn.rs:58:9\n 16: phd_runner::execute::run_tests_with_ctx::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/runner/src/execute.rs:105:13\n 17: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:328:17\n 18: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/loom/std/unsafe_cell.rs:16:9\n 19: tokio::runtime::task::core::Core<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:317:13\n 20: tokio::runtime::task::harness::poll_future::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:485:19\n 21: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:272:9\n 22: std::panicking::try::do_call\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:557:40\n 23: __rust_try\n 24: std::panicking::try\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:521:19\n 25: std::panic::catch_unwind\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs:350:14\n 26: tokio::runtime::task::harness::poll_future\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:473:18\n 27: tokio::runtime::task::harness::Harness<T,S>::poll_inner\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:208:27\n 28: tokio::runtime::task::harness::Harness<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:153:15\n 29: tokio::runtime::task::raw::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:271:5\n 30: tokio::runtime::task::raw::RawTask::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:201:18\n 31: tokio::runtime::task::LocalNotified<S>::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/mod.rs:427:9\n 32: tokio::runtime::scheduler::multi_thread::worker::Context::run_task::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:657:17\n 33: tokio::runtime::coop::with_budget\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/coop.rs:107:5\n 34: tokio::runtime::coop::budget\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/coop.rs:73:5\n 35: tokio::runtime::scheduler::multi_thread::worker::Context::run_task\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:593:9\n 36: tokio::runtime::scheduler::multi_thread::worker::Context::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:544:24\n 37: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:509:21\n 38: tokio::runtime::context::scoped::Scoped<T>::set\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context/scoped.rs:40:9\n 39: tokio::runtime::context::set_scheduler::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context.rs:180:26\n 40: std::thread::local::LocalKey<T>::try_with\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/local.rs:283:12\n 41: std::thread::local::LocalKey<T>::with\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/local.rs:260:9\n 42: tokio::runtime::context::set_scheduler\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context.rs:180:9\n 43: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:504:9\n 44: tokio::runtime::context::runtime::enter_runtime\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context/runtime.rs:65:16\n 45: tokio::runtime::scheduler::multi_thread::worker::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:496:5\n 46: tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:462:45\n 47: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/task.rs:42:21\n 48: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:328:17\n 49: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/loom/std/unsafe_cell.rs:16:9\n 50: tokio::runtime::task::core::Core<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:317:13\n 51: tokio::runtime::task::harness::poll_future::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:485:19\n 52: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:272:9\n 53: std::panicking::try::do_call\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:557:40\n 54: __rust_try\n 55: std::panicking::try\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:521:19\n 56: std::panic::catch_unwind\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs:350:14\n 57: tokio::runtime::task::harness::poll_future\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:473:18\n 58: tokio::runtime::task::harness::Harness<T,S>::poll_inner\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:208:27\n 59: tokio::runtime::task::harness::Harness<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:153:15\n 60: tokio::runtime::task::raw::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:271:5\n 61: tokio::runtime::task::raw::RawTask::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:201:18\n 62: tokio::runtime::task::UnownedTask<S>::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/mod.rs:464:9\n 63: tokio::runtime::blocking::pool::Task::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/pool.rs:160:9\n 64: tokio::runtime::blocking::pool::Inner::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/pool.rs:518:17\n 65: tokio::runtime::blocking::pool::Spawner::spawn_thread::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/pool.rs:476:13\n 66: std::sys::backtrace::__rust_begin_short_backtrace\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/sys/backtrace.rs:152:18\n 67: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/mod.rs:538:17\n 68: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:272:9\n 69: std::panicking::try::do_call\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:557:40\n 70: __rust_try\n 71: std::panicking::try\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:521:19\n 72: std::panic::catch_unwind\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs:350:14\n 73: std::thread::Builder::spawn_unchecked_::{{closure}}\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/mod.rs:537:30\n 74: core::ops::function::FnOnce::call_once{{vtable.shim}}\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/ops/function.rs:250:5\n 75: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/alloc/src/boxed.rs:2070:9\n 76: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/alloc/src/boxed.rs:2070:9\n 77: std::sys::pal::unix::thread::Thread::new::thread_start\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/sys/pal/unix/thread.rs:108:17\n 78: _thrp_setup\n 79: <unknown>","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.985136486Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
2282024-09-18T18:28:17.707Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:17.985226518Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
2292024-09-18T18:28:18.023Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.346266316Z","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":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2302024-09-18T18:28:18.161Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.484519935Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2312024-09-18T18:28:18.185Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.484587105Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-6c097792-b380-45c4-99e6-f9ccff525ba7\"]","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2322024-09-18T18:28:18.209Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.519067307Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2332024-09-18T18:28:18.209Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.519130877Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-454ca2f4-334e-48a4-bdc0-a0eefcaf1c52\"]","verb":"destroy","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back"}
2342024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545027286Z","target":"phd_framework::test_vm","line":1017,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_and_back","vm_id":"1ac4585f-0fce-463f-be7c-77197a03c024","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":662}
2352024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545079957Z","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":72188}
2362024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.54529324Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":560}
2372024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545344721Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
2382024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545378932Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
2392024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545407602Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
2402024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545503023Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
2412024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545589645Z","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"}
2422024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545757347Z","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"}
2432024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545809478Z","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"}
2442024-09-18T18:28:18.235Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.545855609Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::serial_history"}
2452024-09-18T18:28:18.259Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.564212931Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 709M 1.80T 709M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
2462024-09-18T18:28:18.259Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.564304083Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-dabc02b7-b0b0-4a2f-b382-295b24c87d30\"]","path":"phd_tests::migrate::from_base::serial_history"}
2472024-09-18T18:28:18.283Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.588354073Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-dabc02b7-b0b0-4a2f-b382-295b24c87d30\", \"phd-artifacts/phd-clone-fcd7c9c6-fb58-4f4a-8a7e-02e8693f4a04\"]","verb":"clone","path":"phd_tests::migrate::from_base::serial_history"}
2482024-09-18T18:28:18.308Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.613142365Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-fcd7c9c6-fb58-4f4a-8a7e-02e8693f4a04\"]","path":"phd_tests::migrate::from_base::serial_history"}
2492024-09-18T18:28:18.308Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.630718425Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-fcd7c9c6-fb58-4f4a-8a7e-02e8693f4a04 0B 1.80T 709M /phd-artifacts/phd-clone-fcd7c9c6-fb58-4f4a-8a7e-02e8693f4a04\n","path":"phd_tests::migrate::from_base::serial_history"}
2502024-09-18T18:28:18.308Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.631387866Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2512024-09-18T18:28:18.333Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.631445137Z","target":"phd_framework::test_vm","line":204,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","vm_name":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
2522024-09-18T18:28:18.333Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.631499747Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/2a13bdc8e33c968b5133ba5d408d0849f32970a6b469b9b9f0be0185bc46f271/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
2532024-09-18T18:28:18.333Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.631578099Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","config_toml_path":"\"/tmp/propolis-phd/migration_serial_history_base.config.toml\"","server_path":"\"/phd-artifacts/2a13bdc8e33c968b5133ba5d408d0849f32970a6b469b9b9f0be0185bc46f271/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::serial_history"}
2542024-09-18T18:28:18.333Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.631619059Z","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"}
2552024-09-18T18:28:18.333Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 875","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.643090706Z","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"}
2562024-09-18T18:28:18.333Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.643635744Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":12}
2572024-09-18T18:28:18.333Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.643774246Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2582024-09-18T18:28:18.333Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:18.644543648Z","target":"phd_framework::test_vm","line":369,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance/spec): error trying to connect: tcp connect error: Connection refused (os error 146)","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2592024-09-18T18:28:18.925Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.248835351Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
2602024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.249596803Z","target":"phd_framework::test_vm","line":428,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { disks: [], nics: [], properties: InstanceProperties { bootrom_id: 00000000-0000-0000-0000-000000000000, description: \"Pheidippides-managed VM\", id: 84cbfc8b-b0b3-4675-863c-23d81fe463e5, image_id: 00000000-0000-0000-0000-000000000000, memory: 512, metadata: InstanceMetadata { project_id: 936fa5ca-a275-48d7-b6fb-3a2bd9d56d54, silo_id: a640620f-12f1-46b4-9720-d7a3d54a6917, sled_id: 24396d95-ab28-4cd1-a362-108e2b4677e6, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"24396d95-ab28-4cd1-a362-108e2b4677e6\" }, name: \"phd-vm-84cbfc8b-b0b3-4675-863c-23d81fe463e5\", vcpus: 2 }, state: Creating }","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2612024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.249672214Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":605,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5"}
2622024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.249740645Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2632024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.249780596Z","target":"phd_framework::test_vm","line":510,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2642024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.250350034Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5"}
2652024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.250404725Z","target":"phd_framework::test_vm","line":762,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2662024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.250448276Z","target":"phd_framework::test_vm","line":711,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"300s","vm":"migration_serial_history_base","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","path":"phd_tests::migrate::from_base::serial_history"}
2672024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.250482366Z","target":"phd_framework::test_vm","line":719,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
2682024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.250513927Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2692024-09-18T18:28:18.971Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:19.250548037Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2702024-09-18T18:28:23.111Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.434738643Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4184,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5"}
2712024-09-18T18:28:23.111Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.434821705Z","target":"phd_framework::test_vm","line":719,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
2722024-09-18T18:28:23.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.434999837Z","target":"phd_framework::test_vm","line":719,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
2732024-09-18T18:28:23.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.435050488Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2742024-09-18T18:28:23.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.435087178Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2752024-09-18T18:28:23.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.45398718Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":18,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5"}
2762024-09-18T18:28:23.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.454125612Z","target":"phd_framework::test_vm","line":759,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2772024-09-18T18:28:23.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.454200303Z","target":"phd_framework::test_vm","line":762,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":4203}
2782024-09-18T18:28:23.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.454449857Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2792024-09-18T18:28:23.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.454500357Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2802024-09-18T18:28:23.160Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.464908888Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5"}
2812024-09-18T18:28:23.160Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.465137221Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2822024-09-18T18:28:23.160Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.465223502Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
2832024-09-18T18:28:23.184Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.497222195Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5"}
2842024-09-18T18:28:23.184Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.501912687Z","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"}
2852024-09-18T18:28:23.184Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.501983188Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
2862024-09-18T18:28:23.184Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.502031339Z","target":"phd_framework::test_vm","line":204,"file":"phd-tests/framework/src/test_vm/mod.rs","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","guest_os_kind":"Alpine","vm_name":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
2872024-09-18T18:28:23.184Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.50208363Z","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"}
2882024-09-18T18:28:23.184Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.502158661Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_addr":"127.0.0.1:9002","server_path":"\"/work/phd-test/propolis-server\"","config_toml_path":"\"/tmp/propolis-phd/migration_serial_history_base_lifecycle_0.config.toml\"","path":"phd_tests::migrate::from_base::serial_history"}
2892024-09-18T18:28:23.184Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.502201392Z","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"}
2902024-09-18T18:28:23.208Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 876","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.520880209Z","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"}
2912024-09-18T18:28:23.208Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.521267275Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","elapsed_milliseconds":19}
2922024-09-18T18:28:23.209Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.521359387Z","target":"phd_framework::test_vm","line":539,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e"}
2932024-09-18T18:28:23.209Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.521417518Z","target":"phd_framework::test_vm","line":572,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"65dae6b8-accf-4004-ae16-c04915dc7f5a","target":"migration_serial_history_base_lifecycle_0","source_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e"}
2942024-09-18T18:28:23.209Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.521474539Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e","vm_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e"}
2952024-09-18T18:28:23.209Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.521952256Z","target":"phd_framework::test_vm","line":369,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance/spec): error trying to connect: tcp connect error: Connection refused (os error 146)","target":"migration_serial_history_base_lifecycle_0","source_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e","vm_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e"}
2962024-09-18T18:28:23.630Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] permanent error from instance_spec_ensure","level":50,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.954435974Z","target":"phd_framework::test_vm","line":373,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Error Response: status: 500 Internal Server Error; headers: {\"content-type\": \"application/json\", \"x-request-id\": \"7452fb5c-6481-4733-8f20-50653908b74f\", \"content-length\": \"124\", \"date\": \"Wed, 18 Sep 2024 18:28:23 GMT\"}; value: Error { error_code: Some(\"Internal\"), message: \"Internal Server Error\", request_id: \"7452fb5c-6481-4733-8f20-50653908b74f\" }","target":"migration_serial_history_base_lifecycle_0","source_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e","vm_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e"}
2972024-09-18T18:28:23.654Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.954704478Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","target_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e","elapsed_milliseconds":433,"target":"migration_serial_history_base_lifecycle_0","source_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base_lifecycle_0","source":"migration_serial_history_base","vm_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e"}
2982024-09-18T18:28:23.654Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.954769879Z","target":"phd_framework::test_vm","line":539,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":433,"target":"migration_serial_history_base_lifecycle_0","source_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base","target_id":"0f8954c2-9916-41c1-a173-16efdd7ed07e"}
2992024-09-18T18:28:23.654Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.954913951Z","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::serial_history"}
3002024-09-18T18:28:23.679Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.985271558Z","target":"phd_framework::test_vm","line":1017,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
3012024-09-18T18:28:23.679Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.986783591Z","target":"phd_framework::test_vm","line":1040,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
3022024-09-18T18:28:23.679Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.9873463Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3032024-09-18T18:28:23.679Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.987465552Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":4738}
3042024-09-18T18:28:23.679Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... FAILED: Error Response: status: 500 Internal Server Error; headers: {\"content-type\": \"application/json\", \"x-request-id\": \"7452fb5c-6481-4733-8f20-50653908b74f\", \"content-length\": \"124\", \"date\": \"Wed, 18 Sep 2024 18:28:23 GMT\"}; value: Error { error_code: Some(\"Internal\"), message: \"Internal Server Error\", request_id: \"7452fb5c-6481-4733-8f20-50653908b74f\" }\n\nStack backtrace:\n 0: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.86/src/backtrace.rs:27:14\n 1: <core::result::Result<T,F> as core::ops::try_trait::FromResidual<core::result::Result<core::convert::Infallible,E>>>::from_residual\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/result.rs:1989:27\n 2: phd_framework::test_vm::TestVm::instance_ensure_internal::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:385:9\n 3: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9\n 4: phd_framework::test_vm::TestVm::instance_ensure_internal::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:290:5\n 5: phd_framework::test_vm::TestVm::migrate_from::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:589:22\n 6: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9\n 7: phd_framework::test_vm::TestVm::migrate_from::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:539:5\n 8: phd_framework::lifecycle::<impl phd_framework::Framework>::lifecycle_test::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/lifecycle.rs:95:26\n 9: phd_tests::migrate::run_serial_history_test::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/tests/src/migrate.rs:399:6\n 10: phd_tests::migrate::from_base::serial_history::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/tests/src/migrate.rs:46:10\n 11: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9\n 12: phd_tests::migrate::from_base::serial_history::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/tests/src/migrate.rs:40:5\n 13: <core::pin::Pin<P> as core::future::future::Future>::poll\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/future/future.rs:123:9\n 14: phd_testcase::TestCase::run::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/testcase/src/lib.rs:79:32\n 15: phd_runner::execute::run_tests_with_ctx::{{closure}}::{{closure}}::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/macros/select.rs:557:49\n 16: <tokio::future::poll_fn::PollFn<F> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/future/poll_fn.rs:58:9\n 17: phd_runner::execute::run_tests_with_ctx::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/runner/src/execute.rs:105:13\n 18: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:328:17\n 19: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/loom/std/unsafe_cell.rs:16:9\n 20: tokio::runtime::task::core::Core<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:317:13\n 21: tokio::runtime::task::harness::poll_future::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:485:19\n 22: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:272:9\n 23: std::panicking::try::do_call\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:557:40\n 24: __rust_try\n 25: std::panicking::try\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:521:19\n 26: std::panic::catch_unwind\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs:350:14\n 27: tokio::runtime::task::harness::poll_future\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:473:18\n 28: tokio::runtime::task::harness::Harness<T,S>::poll_inner\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:208:27\n 29: tokio::runtime::task::harness::Harness<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:153:15\n 30: tokio::runtime::task::raw::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:271:5\n 31: tokio::runtime::task::raw::RawTask::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:201:18\n 32: tokio::runtime::task::LocalNotified<S>::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/mod.rs:427:9\n 33: tokio::runtime::scheduler::multi_thread::worker::Context::run_task::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:657:17\n 34: tokio::runtime::coop::with_budget\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/coop.rs:107:5\n 35: tokio::runtime::coop::budget\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/coop.rs:73:5\n 36: tokio::runtime::scheduler::multi_thread::worker::Context::run_task\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:593:9\n 37: tokio::runtime::scheduler::multi_thread::worker::Context::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:544:24\n 38: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:509:21\n 39: tokio::runtime::context::scoped::Scoped<T>::set\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context/scoped.rs:40:9\n 40: tokio::runtime::context::set_scheduler::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context.rs:180:26\n 41: std::thread::local::LocalKey<T>::try_with\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/local.rs:283:12\n 42: std::thread::local::LocalKey<T>::with\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/local.rs:260:9\n 43: tokio::runtime::context::set_scheduler\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context.rs:180:9\n 44: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:504:9\n 45: tokio::runtime::context::runtime::enter_runtime\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context/runtime.rs:65:16\n 46: tokio::runtime::scheduler::multi_thread::worker::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:496:5\n 47: tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:462:45\n 48: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/task.rs:42:21\n 49: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:328:17\n 50: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/loom/std/unsafe_cell.rs:16:9\n 51: tokio::runtime::task::core::Core<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:317:13\n 52: tokio::runtime::task::harness::poll_future::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:485:19\n 53: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:272:9\n 54: std::panicking::try::do_call\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:557:40\n 55: __rust_try\n 56: std::panicking::try\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:521:19\n 57: std::panic::catch_unwind\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs:350:14\n 58: tokio::runtime::task::harness::poll_future\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:473:18\n 59: tokio::runtime::task::harness::Harness<T,S>::poll_inner\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:208:27\n 60: tokio::runtime::task::harness::Harness<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:153:15\n 61: tokio::runtime::task::raw::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:271:5\n 62: tokio::runtime::task::raw::RawTask::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:201:18\n 63: tokio::runtime::task::UnownedTask<S>::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/mod.rs:464:9\n 64: tokio::runtime::blocking::pool::Task::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/pool.rs:160:9\n 65: tokio::runtime::blocking::pool::Inner::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/pool.rs:518:17\n 66: tokio::runtime::blocking::pool::Spawner::spawn_thread::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/pool.rs:476:13\n 67: std::sys::backtrace::__rust_begin_short_backtrace\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/sys/backtrace.rs:152:18\n 68: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/mod.rs:538:17\n 69: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:272:9\n 70: std::panicking::try::do_call\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:557:40\n 71: __rust_try\n 72: std::panicking::try\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:521:19\n 73: std::panic::catch_unwind\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs:350:14\n 74: std::thread::Builder::spawn_unchecked_::{{closure}}\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/mod.rs:537:30\n 75: core::ops::function::FnOnce::call_once{{vtable.shim}}\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/ops/function.rs:250:5\n 76: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/alloc/src/boxed.rs:2070:9\n 77: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/alloc/src/boxed.rs:2070:9\n 78: std::sys::pal::unix::thread::Thread::new::thread_start\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/sys/pal/unix/thread.rs:108:17\n 79: _thrp_setup\n 80: <unknown>","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.987667585Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3052024-09-18T18:28:23.679Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:23.987720576Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3062024-09-18T18:28:23.974Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.297918052Z","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::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
3072024-09-18T18:28:24.099Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.423303802Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
3082024-09-18T18:28:24.123Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.423394933Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-fcd7c9c6-fb58-4f4a-8a7e-02e8693f4a04\"]","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
3092024-09-18T18:28:24.147Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.461367168Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
3102024-09-18T18:28:24.147Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.461424189Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-dabc02b7-b0b0-4a2f-b382-295b24c87d30\"]","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5","vm":"migration_serial_history_base"}
3112024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491129456Z","target":"phd_framework::test_vm","line":1017,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":505,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"84cbfc8b-b0b3-4675-863c-23d81fe463e5"}
3122024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491190327Z","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":5945}
3132024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.49139873Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":503}
3142024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491456951Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3152024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491486752Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3162024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491514182Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3172024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491625864Z","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"}
3182024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491717715Z","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"}
3192024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491887498Z","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"}
3202024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491940959Z","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"}
3212024-09-18T18:28:24.172Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.491988369Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3222024-09-18T18:28:24.196Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.509121063Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 710M 1.80T 709M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3232024-09-18T18:28:24.196Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.509218025Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-b63c14a9-6843-459f-9190-4cca95f7a804\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3242024-09-18T18:28:24.220Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.532877689Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-b63c14a9-6843-459f-9190-4cca95f7a804\", \"phd-artifacts/phd-clone-c1dab74c-1a6b-44f2-b419-7ef9dc2a058b\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3252024-09-18T18:28:24.245Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.556663535Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-c1dab74c-1a6b-44f2-b419-7ef9dc2a058b\"]","verb":"list","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3262024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.573061828Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-c1dab74c-1a6b-44f2-b419-7ef9dc2a058b 0B 1.80T 709M /phd-artifacts/phd-clone-c1dab74c-1a6b-44f2-b419-7ef9dc2a058b\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3272024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.573655887Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3282024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.573721408Z","target":"phd_framework::test_vm","line":204,"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"}
3292024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.573774768Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/2a13bdc8e33c968b5133ba5d408d0849f32970a6b469b9b9f0be0185bc46f271/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3302024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.57385235Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","config_toml_path":"\"/tmp/propolis-phd/migration_from_base.config.toml\"","server_path":"\"/phd-artifacts/2a13bdc8e33c968b5133ba5d408d0849f32970a6b469b9b9f0be0185bc46f271/propolis-server\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3312024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.57389606Z","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"}
3322024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 885","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.584140758Z","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"}
3332024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.584511204Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3342024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.584592775Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3352024-09-18T18:28:24.269Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:24.585085193Z","target":"phd_framework::test_vm","line":369,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9000/instance/spec): error trying to connect: tcp connect error: Connection refused (os error 146)","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3362024-09-18T18:28:24.907Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.231192589Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3372024-09-18T18:28:24.953Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.232438369Z","target":"phd_framework::test_vm","line":428,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { disks: [], nics: [], properties: InstanceProperties { bootrom_id: 00000000-0000-0000-0000-000000000000, description: \"Pheidippides-managed VM\", id: 66c036a3-84a3-41f5-9879-950dd12fd6c9, image_id: 00000000-0000-0000-0000-000000000000, memory: 512, metadata: InstanceMetadata { project_id: 58a26037-b2ed-4933-bd4b-34c7384b4aea, silo_id: 6e295296-b5c5-43f6-a60a-8d3cb626f4eb, sled_id: 37eb1662-0a26-42a8-90fb-8f59ff09cc89, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"37eb1662-0a26-42a8-90fb-8f59ff09cc89\" }, name: \"phd-vm-66c036a3-84a3-41f5-9879-950dd12fd6c9\", vcpus: 2 }, state: Creating }","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3382024-09-18T18:28:24.953Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.23253944Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":647,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3392024-09-18T18:28:24.953Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.232611621Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3402024-09-18T18:28:24.954Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.232654482Z","target":"phd_framework::test_vm","line":510,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3412024-09-18T18:28:24.954Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.233301582Z","target":"phd_framework::test_vm","line":505,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":0,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3422024-09-18T18:28:24.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.233357523Z","target":"phd_framework::test_vm","line":762,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3432024-09-18T18:28:24.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.233401974Z","target":"phd_framework::test_vm","line":711,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3442024-09-18T18:28:24.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.233436674Z","target":"phd_framework::test_vm","line":719,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3452024-09-18T18:28:24.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.233470404Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3462024-09-18T18:28:24.954Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:25.233504675Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3472024-09-18T18:28:29.111Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.433321721Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":4199,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3482024-09-18T18:28:29.111Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.433398892Z","target":"phd_framework::test_vm","line":719,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3492024-09-18T18:28:29.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.433581915Z","target":"phd_framework::test_vm","line":719,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3502024-09-18T18:28:29.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.433634246Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3512024-09-18T18:28:29.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.433670897Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3522024-09-18T18:28:29.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.451569772Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":17,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3532024-09-18T18:28:29.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.451717074Z","target":"phd_framework::test_vm","line":759,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3542024-09-18T18:28:29.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.451792836Z","target":"phd_framework::test_vm","line":762,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4218,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3552024-09-18T18:28:29.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.451989308Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3562024-09-18T18:28:29.135Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.452036319Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3572024-09-18T18:28:29.160Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.462399319Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":10,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3582024-09-18T18:28:29.160Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.462609352Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3592024-09-18T18:28:29.160Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.462699744Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3602024-09-18T18:28:29.184Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.484192064Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":21,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3612024-09-18T18:28:29.184Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.484342107Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3622024-09-18T18:28:29.184Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.484393898Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3632024-09-18T18:28:29.184Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.495873314Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":11,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3642024-09-18T18:28:29.184Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.496107948Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3652024-09-18T18:28:29.184Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.496190469Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3662024-09-18T18:28:29.209Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.528925283Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3672024-09-18T18:28:29.209Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.529142766Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3682024-09-18T18:28:29.209Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.529221037Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3692024-09-18T18:28:29.233Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.540614593Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":11,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3702024-09-18T18:28:29.233Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.540804596Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3712024-09-18T18:28:29.233Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.540881037Z","target":"phd_framework::test_vm","line":784,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3722024-09-18T18:28:29.257Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.573577691Z","target":"phd_framework::test_vm","line":777,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":32,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
3732024-09-18T18:28:29.257Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.573730813Z","target":"phd_framework::lifecycle","line":74,"file":"phd-tests/framework/src/lifecycle.rs","propolis_artifact":"__DEFAULT_PROPOLIS","vm_name":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3742024-09-18T18:28:29.257Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.573855175Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3752024-09-18T18:28:29.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.573944886Z","target":"phd_framework::test_vm","line":204,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_lifecycle_0","guest_os_kind":"Alpine","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3762024-09-18T18:28:29.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.574011377Z","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"}
3772024-09-18T18:28:29.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.574098228Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","config_toml_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.config.toml\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3782024-09-18T18:28:29.257Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.574145059Z","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_lifecycle_0.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3792024-09-18T18:28:29.282Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 886","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.592942549Z","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"}
3802024-09-18T18:28:29.282Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.593482227Z","target":"phd_framework::test_vm","line":186,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":19,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
3812024-09-18T18:28:29.282Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.593635149Z","target":"phd_framework::test_vm","line":539,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","target_id":"3130664e-bb28-4862-8f47-a78a5f770fad","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base"}
3822024-09-18T18:28:29.282Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.59370143Z","target":"phd_framework::test_vm","line":572,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"9b2af353-0f01-4e9e-9c3c-23daf43c5099","timeout_duration":"45s","source_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","target_id":"3130664e-bb28-4862-8f47-a78a5f770fad","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base"}
3832024-09-18T18:28:29.282Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.593757211Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","target_id":"3130664e-bb28-4862-8f47-a78a5f770fad","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source":"migration_from_base","vm_id":"3130664e-bb28-4862-8f47-a78a5f770fad"}
3842024-09-18T18:28:29.282Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:29.594222898Z","target":"phd_framework::test_vm","line":369,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9002/instance/spec): error trying to connect: tcp connect error: Connection refused (os error 146)","source_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","target_id":"3130664e-bb28-4862-8f47-a78a5f770fad","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source":"migration_from_base","vm_id":"3130664e-bb28-4862-8f47-a78a5f770fad"}
3852024-09-18T18:28:29.944Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] permanent error from instance_spec_ensure","level":50,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.267728167Z","target":"phd_framework::test_vm","line":373,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Error Response: status: 500 Internal Server Error; headers: {\"content-type\": \"application/json\", \"x-request-id\": \"57a825b2-6381-40f0-91ad-fdc51c7ab453\", \"content-length\": \"124\", \"date\": \"Wed, 18 Sep 2024 18:28:30 GMT\"}; value: Error { error_code: Some(\"Internal\"), message: \"Internal Server Error\", request_id: \"57a825b2-6381-40f0-91ad-fdc51c7ab453\" }","source_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","target_id":"3130664e-bb28-4862-8f47-a78a5f770fad","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source":"migration_from_base","vm_id":"3130664e-bb28-4862-8f47-a78a5f770fad"}
3862024-09-18T18:28:29.968Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.267961541Z","target":"phd_framework::test_vm","line":290,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","target_id":"3130664e-bb28-4862-8f47-a78a5f770fad","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"3130664e-bb28-4862-8f47-a78a5f770fad","target":"migration_from_base_lifecycle_0","vm":"migration_from_base_lifecycle_0","source":"migration_from_base","elapsed_milliseconds":674}
3872024-09-18T18:28:29.968Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.268017431Z","target":"phd_framework::test_vm","line":539,"file":"phd-tests/framework/src/test_vm/mod.rs","source_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","target_id":"3130664e-bb28-4862-8f47-a78a5f770fad","path":"phd_tests::migrate::from_base::can_migrate_from_base","target":"migration_from_base_lifecycle_0","source":"migration_from_base","elapsed_milliseconds":674}
3882024-09-18T18:28:29.968Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.268143553Z","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"}
3892024-09-18T18:28:30.038Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.293230439Z","target":"phd_framework::test_vm","line":1017,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3902024-09-18T18:28:30.038Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.294212805Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3912024-09-18T18:28:30.038Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.294344207Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":5063}
3922024-09-18T18:28:30.038Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... FAILED: Error Response: status: 500 Internal Server Error; headers: {\"content-type\": \"application/json\", \"x-request-id\": \"57a825b2-6381-40f0-91ad-fdc51c7ab453\", \"content-length\": \"124\", \"date\": \"Wed, 18 Sep 2024 18:28:30 GMT\"}; value: Error { error_code: Some(\"Internal\"), message: \"Internal Server Error\", request_id: \"57a825b2-6381-40f0-91ad-fdc51c7ab453\" }\n\nStack backtrace:\n 0: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.86/src/backtrace.rs:27:14\n 1: <core::result::Result<T,F> as core::ops::try_trait::FromResidual<core::result::Result<core::convert::Infallible,E>>>::from_residual\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/result.rs:1989:27\n 2: phd_framework::test_vm::TestVm::instance_ensure_internal::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:385:9\n 3: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9\n 4: phd_framework::test_vm::TestVm::instance_ensure_internal::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:290:5\n 5: phd_framework::test_vm::TestVm::migrate_from::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:589:22\n 6: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9\n 7: phd_framework::test_vm::TestVm::migrate_from::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/test_vm/mod.rs:539:5\n 8: phd_framework::lifecycle::<impl phd_framework::Framework>::lifecycle_test::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/framework/src/lifecycle.rs:95:26\n 9: phd_tests::migrate::run_smoke_test::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/tests/src/migrate.rs:361:6\n 10: phd_tests::migrate::from_base::can_migrate_from_base::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/tests/src/migrate.rs:37:14\n 11: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9\n 12: phd_tests::migrate::from_base::can_migrate_from_base::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/tests/src/migrate.rs:34:5\n 13: <core::pin::Pin<P> as core::future::future::Future>::poll\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/future/future.rs:123:9\n 14: phd_testcase::TestCase::run::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/testcase/src/lib.rs:79:32\n 15: phd_runner::execute::run_tests_with_ctx::{{closure}}::{{closure}}::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/macros/select.rs:557:49\n 16: <tokio::future::poll_fn::PollFn<F> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/future/poll_fn.rs:58:9\n 17: phd_runner::execute::run_tests_with_ctx::{{closure}}::{{closure}}\n at ./oxidecomputer/propolis/phd-tests/runner/src/execute.rs:105:13\n 18: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:328:17\n 19: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/loom/std/unsafe_cell.rs:16:9\n 20: tokio::runtime::task::core::Core<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:317:13\n 21: tokio::runtime::task::harness::poll_future::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:485:19\n 22: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:272:9\n 23: std::panicking::try::do_call\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:557:40\n 24: __rust_try\n 25: std::panicking::try\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:521:19\n 26: std::panic::catch_unwind\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs:350:14\n 27: tokio::runtime::task::harness::poll_future\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:473:18\n 28: tokio::runtime::task::harness::Harness<T,S>::poll_inner\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:208:27\n 29: tokio::runtime::task::harness::Harness<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:153:15\n 30: tokio::runtime::task::raw::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:271:5\n 31: tokio::runtime::task::raw::RawTask::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:201:18\n 32: tokio::runtime::task::LocalNotified<S>::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/mod.rs:427:9\n 33: tokio::runtime::scheduler::multi_thread::worker::Context::run_task::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:657:17\n 34: tokio::runtime::coop::with_budget\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/coop.rs:107:5\n 35: tokio::runtime::coop::budget\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/coop.rs:73:5\n 36: tokio::runtime::scheduler::multi_thread::worker::Context::run_task\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:593:9\n 37: tokio::runtime::scheduler::multi_thread::worker::Context::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:544:24\n 38: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:509:21\n 39: tokio::runtime::context::scoped::Scoped<T>::set\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context/scoped.rs:40:9\n 40: tokio::runtime::context::set_scheduler::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context.rs:180:26\n 41: std::thread::local::LocalKey<T>::try_with\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/local.rs:283:12\n 42: std::thread::local::LocalKey<T>::with\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/local.rs:260:9\n 43: tokio::runtime::context::set_scheduler\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context.rs:180:9\n 44: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:504:9\n 45: tokio::runtime::context::runtime::enter_runtime\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context/runtime.rs:65:16\n 46: tokio::runtime::scheduler::multi_thread::worker::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:496:5\n 47: tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/multi_thread/worker.rs:462:45\n 48: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/task.rs:42:21\n 49: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:328:17\n 50: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/loom/std/unsafe_cell.rs:16:9\n 51: tokio::runtime::task::core::Core<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/core.rs:317:13\n 52: tokio::runtime::task::harness::poll_future::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:485:19\n 53: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:272:9\n 54: std::panicking::try::do_call\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:557:40\n 55: __rust_try\n 56: std::panicking::try\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:521:19\n 57: std::panic::catch_unwind\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs:350:14\n 58: tokio::runtime::task::harness::poll_future\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:473:18\n 59: tokio::runtime::task::harness::Harness<T,S>::poll_inner\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:208:27\n 60: tokio::runtime::task::harness::Harness<T,S>::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/harness.rs:153:15\n 61: tokio::runtime::task::raw::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:271:5\n 62: tokio::runtime::task::raw::RawTask::poll\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/raw.rs:201:18\n 63: tokio::runtime::task::UnownedTask<S>::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/task/mod.rs:464:9\n 64: tokio::runtime::blocking::pool::Task::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/pool.rs:160:9\n 65: tokio::runtime::blocking::pool::Inner::run\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/pool.rs:518:17\n 66: tokio::runtime::blocking::pool::Spawner::spawn_thread::{{closure}}\n at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/blocking/pool.rs:476:13\n 67: std::sys::backtrace::__rust_begin_short_backtrace\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/sys/backtrace.rs:152:18\n 68: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/mod.rs:538:17\n 69: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:272:9\n 70: std::panicking::try::do_call\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:557:40\n 71: __rust_try\n 72: std::panicking::try\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:521:19\n 73: std::panic::catch_unwind\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs:350:14\n 74: std::thread::Builder::spawn_unchecked_::{{closure}}\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/mod.rs:537:30\n 75: core::ops::function::FnOnce::call_once{{vtable.shim}}\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/ops/function.rs:250:5\n 76: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/alloc/src/boxed.rs:2070:9\n 77: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/alloc/src/boxed.rs:2070:9\n 78: std::sys::pal::unix::thread::Thread::new::thread_start\n at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/sys/pal/unix/thread.rs:108:17\n 79: _thrp_setup\n 80: <unknown>","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.294514719Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3932024-09-18T18:28:30.038Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.2945678Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3942024-09-18T18:28:30.038Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.294834474Z","target":"phd_framework::test_vm","line":1040,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3952024-09-18T18:28:30.476Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.800025812Z","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":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3962024-09-18T18:28:30.609Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.933260393Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3972024-09-18T18:28:30.633Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.933359114Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-c1dab74c-1a6b-44f2-b419-7ef9dc2a058b\"]","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3982024-09-18T18:28:30.658Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.964781598Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
3992024-09-18T18:28:30.658Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.964837499Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-b63c14a9-6843-459f-9190-4cca95f7a804\"]","vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base"}
4002024-09-18T18:28:30.682Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.989461788Z","target":"phd_framework::test_vm","line":1017,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm":"migration_from_base","elapsed_milliseconds":696,"vm_id":"66c036a3-84a3-41f5-9879-950dd12fd6c9"}
4012024-09-18T18:28:30.682Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.989515969Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":6497,"path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4022024-09-18T18:28:30.683Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.989766262Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":695}
4032024-09-18T18:28:30.683Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.989846964Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
4042024-09-18T18:28:30.683Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.989875704Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4052024-09-18T18:28:30.683Z
4062024-09-18T18:28:30.683Zfailures:
4072024-09-18T18:28:30.683Z phd_tests::migrate::from_base::migration_from_base_and_back
4082024-09-18T18:28:30.683Z phd_tests::migrate::from_base::serial_history
4092024-09-18T18:28:30.683Z phd_tests::migrate::from_base::can_migrate_from_base
4102024-09-18T18:28:30.683Z
4112024-09-18T18:28:30.683Ztest result: FAILED. 0 passed; 3 failed; 0 skipped; 0 not run; finished in 84.63s
4122024-09-18T18:28:30.683Z
4132024-09-18T18:28:30.683Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"buskin","pid":860,"time":"2024-09-18T18:28:30.989999356Z","target":"phd_runner","line":40,"file":"phd-tests/runner/src/main.rs","exit_code":3}
4142024-09-18T18:28:30.746Z
4152024-09-18T18:28:30.771Zreal 1:25.366348584
4162024-09-18T18:28:30.771Zuser 22.671947483
4172024-09-18T18:28:30.771Zsys 13.052920236
4182024-09-18T18:28:30.771Ztrap 0.002718795
4192024-09-18T18:28:30.771Ztflt 0.000633139
4202024-09-18T18:28:30.771Zdflt 0.000183922
4212024-09-18T18:28:30.771Zkflt 0.000126818
4222024-09-18T18:28:30.771Zlock 1:15:34.634906100
4232024-09-18T18:28:30.771Zslp 2:09.056097998
4242024-09-18T18:28:30.771Zlat 0.161397894
4252024-09-18T18:28:30.771Zstop 16.834416804
4262024-09-18T18:28:30.771Z+ failcount=3
4272024-09-18T18:28:30.771Z+ set -e
4282024-09-18T18:28:30.771Z+ 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.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 -C /tmp/propolis-phd /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.config.toml /tmp/propolis-phd/migration_from_base_and_back.config.toml /tmp/propolis-phd/migration_from_base_lifecycle_0.config.toml /tmp/propolis-phd/migration_from_base.config.toml /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.config.toml /tmp/propolis-phd/migration_serial_history_base.config.toml
4292024-09-18T18:28:30.771ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
4302024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log 0K
4312024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log 5K
4322024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_and_back.serial.log 7K
4332024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_and_back.stderr.log 0K
4342024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_and_back.stdout.log 32K
4352024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log 0K
4362024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log 5K
4372024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base.serial.log 7K
4382024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base.stderr.log 0K
4392024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base.stdout.log 32K
4402024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log 0K
4412024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log 5K
4422024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_serial_history_base.serial.log 7K
4432024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_serial_history_base.stderr.log 0K
4442024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_serial_history_base.stdout.log 33K
4452024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.config.toml 1K
4462024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_and_back.config.toml 1K
4472024-09-18T18:28:30.771Za /tmp/propolis-phd/migration_from_base_lifecycle_0.config.toml 1K
4482024-09-18T18:28:30.772Za /tmp/propolis-phd/migration_from_base.config.toml 1K
4492024-09-18T18:28:30.772Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.config.toml 1K
4502024-09-18T18:28:30.772Za /tmp/propolis-phd/migration_serial_history_base.config.toml 1K
4512024-09-18T18:28:30.772Z+ exitcode=0
4522024-09-18T18:28:30.772Z+ '[' 3 -eq 0 ']'
4532024-09-18T18:28:30.772Z+ echo
4542024-09-18T18:28:30.772Z
4552024-09-18T18:28:30.772Z+ echo 'SOME TESTS FAILED'
4562024-09-18T18:28:30.772ZSOME TESTS FAILED
4572024-09-18T18:28:30.772Z
4582024-09-18T18:28:30.772Z+ echo
4592024-09-18T18:28:30.772Z+ exitcode=1
4602024-09-18T18:28:30.772Z+ find /dev/vmm -mindepth 1 -maxdepth 1
4612024-09-18T18:28:30.772Z+ read
4622024-09-18T18:28:30.772Z+ exit 1
4632024-09-18T18:28:30.772Zprocess exited: duration 95215 ms, exit code 1
 
4642024-09-18T18:28:30.847Zfound 2 output files
4652024-09-18T18:28:30.847Zuploading: /tmp/phd-runner.log (157819 bytes)
4662024-09-18T18:28:31.990Zuploaded: /tmp/phd-runner.log
4672024-09-18T18:28:31.991Zuploading: /tmp/phd-tmp-files.tar.gz (17259 bytes)
4682024-09-18T18:28:33.132Zuploaded: /tmp/phd-tmp-files.tar.gz