01JE7DA220SF9Q35SJKYBKX7A3: 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: 01JE7DAGYQGBCP58ED3T7F8YQZ

Tags:

Artefacts:

Output:

SEQ GLOBAL TIME DETAILS
12024-12-03T23:30:12.637Zjob dependencies complete; ready to run (waiting for 7 m 31 s)
22024-12-04T00:56:56.990Zjob assigned to worker 01JE7JDMPZ4DCZZ6AT39481VR7 [factory lab, sock/10712] (queued for 1 h 26 m 44 s)
32024-12-04T00:56:57.270Zhttp://172.20.0.5:9969/ipxe/sock... ok
42024-12-04T00:56:57.318Zhttp://172.20.0.5:9969/os/sock/platform/i86pc/kernel/amd64/unix... ok
52024-12-04T00:56:57.352Zhttp://172.20.0.5:9969/os/sock/platform/i86pc/amd64/boot_archive... ok
62024-12-04T00:56:57.385Zhttp://172.20.0.5:9969/os/sock/platform/i86pc/amd64/boot_archive.hash... ok
72024-12-04T00:56:57.419Zhttp://172.20.0.5:9969/postboot/sock... ok
82024-12-04T00:56:57.452ZwcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U wcnCroia6U
92024-12-04T00:56:57.486Zcpu0: microcode has been updated from version 0xa001133 to 0xa0011d5
102024-12-04T00:56:57.519ZOxide Helios Version helios-2.0.23032 64-bit
112024-12-04T00:56:57.553ZConfiguring devices.
122024-12-04T00:56:57.588Z##################################################
132024-12-04T00:56:57.621Z#### ############# ##
142024-12-04T00:56:57.655Z### ### ############ ##
152024-12-04T00:56:57.689Z## ### # ## ### ## Oxide Computer Company ##
162024-12-04T00:56:57.722Z## ## ## ### # ### ##
172024-12-04T00:56:57.776Z## # ### #### #### This Station Under ##
182024-12-04T00:56:57.811Z### ### #### # ### Computer Control ##
192024-12-04T00:56:57.845Z#### #### ### ## ##
202024-12-04T00:56:57.878Z##################################################
212024-12-04T00:56:57.911ZHostname: sock
222024-12-04T00:56:57.945ZLoading smf(7) service descriptions:
232024-12-04T00:56:58.975Zdownloading input: /input/phd-build/out/phd-run-with-args.sh
242024-12-04T00:56:59.011Zdownloaded input: /input/phd-build/out/phd-run-with-args.sh
252024-12-04T00:56:59.011Zdownloading input: /input/phd-build/out/phd-runner.sha256.txt
262024-12-04T00:56:59.046Zdownloaded input: /input/phd-build/out/phd-runner.sha256.txt
272024-12-04T00:56:59.069Zdownloading input: /input/phd-build/out/phd-runner.tar.gz
282024-12-04T00:57:11.018Zdownloaded input: /input/phd-build/out/phd-runner.tar.gz
292024-12-04T00:57:11.018Zdownloading input: /input/phd-build/out/propolis-server-debug.sha256.txt
302024-12-04T00:57:11.054Zdownloaded input: /input/phd-build/out/propolis-server-debug.sha256.txt
312024-12-04T00:57:11.054Zdownloading input: /input/phd-build/out/propolis-server-debug.tar.gz
322024-12-04T00:57:35.430Zdownloaded input: /input/phd-build/out/propolis-server-debug.tar.gz
 
332024-12-04T00:57:35.455Zstarting task 0: "setup"
342024-12-04T00:57:35.455Z++ uname -s
352024-12-04T00:57:35.455Z+ kern=SunOS
362024-12-04T00:57:35.455Z+ case "$kern" in
372024-12-04T00:57:35.455Z+ groupadd -g 12345 build
382024-12-04T00:57:35.455Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
392024-12-04T00:57:37.449Z+ zfs create -o mountpoint=/work rpool/work
402024-12-04T00:57:37.474Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
412024-12-04T00:57:37.474Z+ home_fs=zfs
422024-12-04T00:57:37.474Z+ [[ zfs == autofs ]]
432024-12-04T00:57:37.474Z+ mkdir -p /home/build
442024-12-04T00:57:37.474Z+ chown build:build /home/build /work
452024-12-04T00:57:39.497Z+ chmod 0700 /home/build /work
462024-12-04T00:57:39.521Zprocess exited: duration 4047 ms, exit code 0
 
472024-12-04T00:57:39.569Zstarting task 1: "authentication"
482024-12-04T00:57:39.610Zprocess exited: duration 41 ms, exit code 0
 
492024-12-04T00:57:39.656Zstarting task 2: "build"
502024-12-04T00:57:39.679Z+ indir=/input
512024-12-04T00:57:39.679Z+ indir_suffix='phd-build/out/*.tar.gz'
522024-12-04T00:57:39.680Z+ phddir=/work/phd-test
532024-12-04T00:57:39.680Z+ pfexec zpool create -f phd-artifacts c1t1d0 c2t1d0
542024-12-04T00:57:39.800Z+ artifactdir=/phd-artifacts
552024-12-04T00:57:39.800Z+ banner Inputs
562024-12-04T00:57:39.824Z ###
572024-12-04T00:57:39.824Z # # # ##### # # ##### ####
582024-12-04T00:57:39.824Z # ## # # # # # # #
592024-12-04T00:57:39.824Z # # # # # # # # # ####
602024-12-04T00:57:39.824Z # # # # ##### # # # #
612024-12-04T00:57:39.824Z # # ## # # # # # #
622024-12-04T00:57:39.824Z ### # # # #### # ####
632024-12-04T00:57:39.824Z
642024-12-04T00:57:39.824Z+ find /input -ls
652024-12-04T00:57:39.824Z 34 1 drwxr-xr-x 3 root root 3 Dec 4 00:56 /input
662024-12-04T00:57:39.824Z 2 1 drwxr-xr-x 3 root root 3 Dec 4 00:56 /input/phd-build
672024-12-04T00:57:39.824Z 3 2 drwxr-xr-x 2 root root 7 Dec 4 00:57 /input/phd-build/out
682024-12-04T00:57:39.824Z 256 1 -rw-r--r-- 1 root root 65 Dec 4 00:57 /input/phd-build/out/propolis-server-debug.sha256.txt
692024-12-04T00:57:39.824Z 128 2 -rw-r--r-- 1 root root 1795 Dec 4 00:56 /input/phd-build/out/phd-run-with-args.sh
702024-12-04T00:57:39.824Z 257 137691 -rw-r--r-- 1 root root 140891555 Dec 4 00:57 /input/phd-build/out/propolis-server-debug.tar.gz
712024-12-04T00:57:39.824Z 129 1 -rw-r--r-- 1 root root 65 Dec 4 00:56 /input/phd-build/out/phd-runner.sha256.txt
722024-12-04T00:57:39.824Z 130 67394 -rw-r--r-- 1 root root 68963885 Dec 4 00:57 /input/phd-build/out/phd-runner.tar.gz
732024-12-04T00:57:39.824Z+ rm -rf /work/phd-test
742024-12-04T00:57:39.824Z+ mkdir /work/phd-test
752024-12-04T00:57:39.824Z+ for p in $indir/$indir_suffix
762024-12-04T00:57:39.824Z+ tar xzvf /input/phd-build/out/phd-runner.tar.gz -C /work/phd-test
772024-12-04T00:57:41.329ZDecompressing '/input/phd-build/out/phd-runner.tar.gz' with '/usr/bin/gzcat'...
782024-12-04T00:57:41.329Zx phd-runner, 245670280 bytes, 479825 tape blocks
792024-12-04T00:57:41.329Zx artifacts.toml, 548 bytes, 2 tape blocks
802024-12-04T00:57:41.352Z++ tar tf /input/phd-build/out/phd-runner.tar.gz
812024-12-04T00:57:42.788Z+ for f in $(tar tf "$p")
822024-12-04T00:57:42.788Z+ chmod +x /work/phd-test/phd-runner
832024-12-04T00:57:42.811Z+ for f in $(tar tf "$p")
842024-12-04T00:57:42.811Z+ chmod +x /work/phd-test/artifacts.toml
852024-12-04T00:57:42.811Z+ for p in $indir/$indir_suffix
862024-12-04T00:57:42.811Z+ tar xzvf /input/phd-build/out/propolis-server-debug.tar.gz -C /work/phd-test
872024-12-04T00:57:46.049ZDecompressing '/input/phd-build/out/propolis-server-debug.tar.gz' with '/usr/bin/gzcat'...
882024-12-04T00:57:46.049Zx propolis-server, 533922080 bytes, 1042817 tape blocks
892024-12-04T00:57:46.071Z++ tar tf /input/phd-build/out/propolis-server-debug.tar.gz
902024-12-04T00:57:48.999Z+ for f in $(tar tf "$p")
912024-12-04T00:57:48.999Z+ chmod +x /work/phd-test/propolis-server
922024-12-04T00:57:49.023Z+ ls /work/phd-test
932024-12-04T00:57:49.023Zartifacts.toml
942024-12-04T00:57:49.023Zphd-runner
952024-12-04T00:57:49.023Zpropolis-server
962024-12-04T00:57:49.023Z+ banner Setup
972024-12-04T00:57:49.023Z #####
982024-12-04T00:57:49.023Z# # ###### ##### # # #####
992024-12-04T00:57:49.023Z# # # # # # #
1002024-12-04T00:57:49.023Z ##### ##### # # # # #
1012024-12-04T00:57:49.023Z # # # # # #####
1022024-12-04T00:57:49.023Z# # # # # # #
1032024-12-04T00:57:49.023Z ##### ###### # #### #
1042024-12-04T00:57:49.023Z
1052024-12-04T00:57:49.023Z+ tmpdir=/tmp/propolis-phd
1062024-12-04T00:57:49.023Z+ '[' '!' -d /tmp/propolis-phd ']'
1072024-12-04T00:57:49.023Z+ mkdir /tmp/propolis-phd
1082024-12-04T00:57:49.023Z+ banner Tests
1092024-12-04T00:57:49.023Z#######
1102024-12-04T00:57:49.023Z # ###### #### ##### ####
1112024-12-04T00:57:49.024Z # # # # #
1122024-12-04T00:57:49.024Z # ##### #### # ####
1132024-12-04T00:57:49.024Z # # # # #
1142024-12-04T00:57:49.024Z # # # # # # #
1152024-12-04T00:57:49.024Z # ###### #### # ####
1162024-12-04T00:57:49.024Z
1172024-12-04T00:57:49.024Z+ runner=/work/phd-test/phd-runner
1182024-12-04T00:57:49.024Z+ artifacts=/work/phd-test/artifacts.toml
1192024-12-04T00:57:49.024Z+ propolis=/work/phd-test/propolis-server
1202024-12-04T00:57:49.024Z+ ls /work/phd-test/phd-runner
1212024-12-04T00:57:49.024Z/work/phd-test/phd-runner
1222024-12-04T00:57:49.024Z+ ls /work/phd-test/artifacts.toml
1232024-12-04T00:57:49.024Z/work/phd-test/artifacts.toml
1242024-12-04T00:57:49.024Z+ ls /work/phd-test/propolis-server
1252024-12-04T00:57:49.024Z/work/phd-test/propolis-server
1262024-12-04T00:57:49.024Z+ args=($runner '--emit-bunyan' 'run' '--propolis-server-cmd' $propolis '--crucible-downstairs-commit' 'auto' '--artifact-toml-path' $artifacts '--tmp-directory' $tmpdir '--artifact-directory' $artifactdir $@)
1272024-12-04T00:57:49.025Z+ set +e
1282024-12-04T00:57:49.025Z+ RUST_BACKTRACE=1
1292024-12-04T00:57:49.025Z+ RUST_LOG=info,phd=debug
1302024-12-04T00:57:49.025Z+ 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-12-04T00:57:49.025Z+ tee /tmp/phd-runner.log
1322024-12-04T00:57:49.048Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:49.488229305Z","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-12-04T00:57:49.072Z{"v":0,"name":"phd-runner","msg":"Created new artifact store from manifest","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:49.490352527Z","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: 469, tv_nsec: 238097104 }, max_elapsed_time: Some(1200s), clock: SystemClock }, remote_server_uris: [\"https://oxide-omicron-build.s3.amazonaws.com\"] } }"}
1342024-12-04T00:57:49.072Z{"v":0,"name":"phd-runner","msg":"Adding Propolis server from local command","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:49.490408228Z","target":"phd_framework::artifacts::store","line":229,"file":"phd-tests/framework/src/artifacts/store.rs","propolis_server_cmd":"/work/phd-test/propolis-server"}
1352024-12-04T00:57:49.072Z{"v":0,"name":"phd-runner","msg":"Adding crucible-downstairs from Buildomat Git revision","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:49.490515212Z","target":"phd_framework::artifacts::store","line":313,"file":"phd-tests/framework/src/artifacts/store.rs","commit":"5a41b826171c7d2a8412fa833377ab1df25ee8ec"}
1362024-12-04T00:57:49.072Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:49.490672636Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","timeout":"600s","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/crucible/nightly-image/5a41b826171c7d2a8412fa833377ab1df25ee8ec/crucible-nightly.sha256.txt"}
1372024-12-04T00:57:49.187Z{"v":0,"name":"phd-runner","msg":"Adding 'current' Propolis server from Buildomat Git branch 'master'","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:49.627097958Z","target":"phd_framework::artifacts::store","line":250,"file":"phd-tests/framework/src/artifacts/store.rs"}
1382024-12-04T00:57:49.634Z{"v":0,"name":"phd-runner","msg":"Downloading file from Buildomat...","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.073743679Z","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/6088629014b1c133950ec8a02c5a47a482121e53/propolis-server.sha256.txt"}
1392024-12-04T00:57:49.738Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.17774147Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs"}
1402024-12-04T00:57:49.761Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_SETUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.177882554Z","target":"phd_runner::fixtures","line":25,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1412024-12-04T00:57:49.761Z{"v":0,"name":"phd-runner","msg":"Running 3 test(s)","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.178067549Z","target":"phd_runner::execute","line":82,"file":"phd-tests/runner/src/execute.rs"}
1422024-12-04T00:57:49.761Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::migration_from_base_and_back","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.178173043Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
1432024-12-04T00:57:49.761Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.178219364Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
1442024-12-04T00:57:49.761Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.178263335Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
1452024-12-04T00:57:49.761Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.178590025Z","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-12-04T00:57:49.761Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.17912496Z","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-12-04T00:57:49.761Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading file from Buildomat...","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.179322146Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/edk2/image_debug/6d92acf0a22718dd4175d7c64dbcf7aaec3740bd/OVMF_CODE.fd","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1482024-12-04T00:57:50.301Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] checking for existing copy of artifact","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.741511317Z","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-12-04T00:57:50.326Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Downloading alpine.iso from https://oxide-omicron-build.s3.amazonaws.com/alpine.iso","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:57:50.741654241Z","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-12-04T00:58:16.901Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.34148058Z","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-12-04T00:58:16.924Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.341601883Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"/phd-artifacts/ba8007f74f9b54fbae3b2520da577831b4834778a498d732f091260c61aa7ca1/alpine.iso\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1522024-12-04T00:58:16.948Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.369487281Z","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-12-04T00:58:16.948Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.369746869Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-cc155ee9-5e5c-4889-8393-0d2dabdf73f7\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1542024-12-04T00:58:16.971Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.397695989Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-cc155ee9-5e5c-4889-8393-0d2dabdf73f7\", \"phd-artifacts/phd-clone-399e408c-32ef-44a8-b661-9e7fb2a503e2\"]","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1552024-12-04T00:58:16.994Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.415063078Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-399e408c-32ef-44a8-b661-9e7fb2a503e2\"]","verb":"list","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1562024-12-04T00:58:16.994Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.427641837Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-399e408c-32ef-44a8-b661-9e7fb2a503e2 0B 1.80T 48.9M /phd-artifacts/phd-clone-399e408c-32ef-44a8-b661-9e7fb2a503e2\n","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1572024-12-04T00:58:16.996Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.42842003Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1582024-12-04T00:58:16.996Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.428496663Z","target":"phd_framework::test_vm","line":206,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1592024-12-04T00:58:16.996Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] checking for existing copy of artifact","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.428553094Z","target":"phd_framework::artifacts::store","line":89,"file":"phd-tests/framework/src/artifacts/store.rs","maybe_path":"/phd-artifacts/7127f9a0268259da63364fdec667cb5b2b55048ae29e6461766495d1b90af32d/propolis-server.tar.gz","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1602024-12-04T00:58:16.996Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Downloading file from Buildomat...","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:17.428610776Z","target":"phd_framework::artifacts::buildomat","line":215,"file":"phd-tests/framework/src/artifacts/buildomat.rs","uri":"https://buildomat.eng.oxide.computer/public/file/oxidecomputer/propolis/phd_build/6088629014b1c133950ec8a02c5a47a482121e53/propolis-server.tar.gz","timeout":"600s","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1612024-12-04T00:58:40.980Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting artifact from tarball","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:41.420488376Z","target":"phd_framework::artifacts::store","line":162,"file":"phd-tests/framework/src/artifacts/store.rs","extracted_path":"/phd-artifacts/7127f9a0268259da63364fdec667cb5b2b55048ae29e6461766495d1b90af32d/propolis-server","untar_path":"propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1622024-12-04T00:58:41.003Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Extracting gzipped tarball...","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:41.4205936Z","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-12-04T00:58:53.780Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.220910054Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/7127f9a0268259da63364fdec667cb5b2b55048ae29e6461766495d1b90af32d/propolis-server\"","config_toml_path":"\"/tmp/propolis-phd/migration_from_base_and_back.config.toml\"","server_addr":"127.0.0.1:9000","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1642024-12-04T00:58:53.804Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.221068549Z","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-12-04T00:58:53.830Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 867","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.271149728Z","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-12-04T00:58:53.854Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.271543449Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":36843,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1672024-12-04T00:58:53.854Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.271768266Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1682024-12-04T00:58:53.854Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.272619051Z","target":"phd_framework::test_vm","line":370,"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)","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1692024-12-04T00:58:54.540Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.980799214Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
1702024-12-04T00:58:54.584Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.981429932Z","target":"phd_framework::test_vm","line":429,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 0f12f658-3236-4169-bf72-0ddaf2a1b396, metadata: InstanceMetadata { project_id: fac095b3-05e9-4ca7-bd03-55c4bca56e74, silo_id: b1f49f1e-5020-48d0-83f6-bd4235504827, sled_id: 8d50fec4-3304-458e-a417-a0a89eb8f3d8, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"8d50fec4-3304-458e-a417-a0a89eb8f3d8\" }, name: \"phd-vm-0f12f658-3236-4169-bf72-0ddaf2a1b396\" }, state: Creating }","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1712024-12-04T00:58:54.584Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.981495414Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":709,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
1722024-12-04T00:58:54.584Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.981572496Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1732024-12-04T00:58:54.585Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.981612207Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1742024-12-04T00:58:54.585Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.982164804Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":0,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
1752024-12-04T00:58:54.585Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.982229166Z","target":"phd_framework::test_vm","line":763,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1762024-12-04T00:58:54.585Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.982294998Z","target":"phd_framework::test_vm","line":712,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","timeout_duration":"300s","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1772024-12-04T00:58:54.585Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.982339509Z","target":"phd_framework::test_vm","line":720,"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-12-04T00:58:54.585Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.98237622Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1792024-12-04T00:58:54.585Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:54.982418641Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost login: ","timeout_duration":"CallerTimeout","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1802024-12-04T00:58:58.773Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.21409314Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4231,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
1812024-12-04T00:58:58.773Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.214169772Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1822024-12-04T00:58:58.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.214393279Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1832024-12-04T00:58:58.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.21444215Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1842024-12-04T00:58:58.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.214477121Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost:~#","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1852024-12-04T00:58:58.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.232227542Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":17,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
1862024-12-04T00:58:58.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.232312184Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1872024-12-04T00:58:58.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.232533151Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1882024-12-04T00:58:58.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.232591353Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1892024-12-04T00:58:58.797Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.232633514Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1902024-12-04T00:58:58.825Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.265407845Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
1912024-12-04T00:58:58.847Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.265514848Z","target":"phd_framework::test_vm","line":760,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1922024-12-04T00:58:58.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.265604541Z","target":"phd_framework::test_vm","line":763,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4283,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1932024-12-04T00:58:58.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.265854368Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1942024-12-04T00:58:58.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.265936561Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar 2> /dev/null","timeout_duration":"Explicit(15s)","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1952024-12-04T00:58:58.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.276295104Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":10,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
1962024-12-04T00:58:58.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.276508771Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1972024-12-04T00:58:58.848Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.276587683Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
1982024-12-04T00:58:58.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.298141596Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":21,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
1992024-12-04T00:58:58.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.29828955Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2002024-12-04T00:58:58.871Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.298340251Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2012024-12-04T00:58:58.872Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.309727125Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
2022024-12-04T00:58:58.872Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.309942371Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2032024-12-04T00:58:58.872Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.310021974Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2042024-12-04T00:58:58.901Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.341898779Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
2052024-12-04T00:58:58.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.342129876Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2062024-12-04T00:58:58.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.342208328Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"sync ./foo.bar","timeout_duration":"Explicit(15s)","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2072024-12-04T00:58:58.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.353647694Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
2082024-12-04T00:58:58.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.353956223Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2092024-12-04T00:58:58.929Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.354041005Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2102024-12-04T00:58:58.952Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.385860118Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":31,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
2112024-12-04T00:58:58.952Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.385991732Z","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"}
2122024-12-04T00:58:58.952Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.386057684Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2132024-12-04T00:58:58.952Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.386108056Z","target":"phd_framework::test_vm","line":206,"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"}
2142024-12-04T00:58:58.952Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Examining locally-sourced artifact","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.386177708Z","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"}
2152024-12-04T00:58:58.952Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Locally-sourced artifact is valid, caching its path","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.386230349Z","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"}
2162024-12-04T00:58:58.952Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.386311092Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/work/phd-test/propolis-server\"","config_toml_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.config.toml\"","server_addr":"127.0.0.1:9002","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2172024-12-04T00:58:58.952Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.386351863Z","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"}
2182024-12-04T00:58:58.975Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 868","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.401675793Z","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"}
2192024-12-04T00:58:58.975Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.401883928Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":15,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2202024-12-04T00:58:58.975Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.401981662Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target":"migration_from_base_and_back_lifecycle_0","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back"}
2212024-12-04T00:58:58.976Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.402040433Z","target":"phd_framework::test_vm","line":573,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"a5fa1929-4cea-4414-9d4a-ba5f171f4d92","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target":"migration_from_base_and_back_lifecycle_0","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back"}
2222024-12-04T00:58:58.977Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.402105715Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target":"migration_from_base_and_back_lifecycle_0","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","source":"migration_from_base_and_back"}
2232024-12-04T00:58:58.977Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.402588449Z","target":"phd_framework::test_vm","line":370,"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)","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target":"migration_from_base_and_back_lifecycle_0","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","source":"migration_from_base_and_back"}
2242024-12-04T00:58:59.359Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.799369438Z","target":"phd_framework::test_vm","line":429,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 1ce07b8a-b6dc-4bf6-b790-60245b6d3119, metadata: InstanceMetadata { project_id: fac095b3-05e9-4ca7-bd03-55c4bca56e74, silo_id: b1f49f1e-5020-48d0-83f6-bd4235504827, sled_id: d23d0251-6f6c-4dc2-9aaf-814f63e33c76, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"d23d0251-6f6c-4dc2-9aaf-814f63e33c76\" }, name: \"phd-vm-1ce07b8a-b6dc-4bf6-b790-60245b6d3119\" }, state: Migrating }","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target":"migration_from_base_and_back_lifecycle_0","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","source":"migration_from_base_and_back"}
2252024-12-04T00:58:59.382Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.799493722Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_0","vm":"migration_from_base_and_back_lifecycle_0","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","source":"migration_from_base_and_back","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":397}
2262024-12-04T00:58:59.382Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:58:59.799558464Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target":"migration_from_base_and_back_lifecycle_0","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"a5fa1929-4cea-4414-9d4a-ba5f171f4d92","source":"migration_from_base_and_back"}
2272024-12-04T00:59:01.872Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:02.312995441Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7760}}"}
2282024-12-04T00:59:02.919Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:03.359574761Z","target":"phd_framework::test_vm","line":607,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target":"migration_from_base_and_back_lifecycle_0","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back"}
2292024-12-04T00:59:02.919Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:03.359625702Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target":"migration_from_base_and_back_lifecycle_0","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"a5fa1929-4cea-4414-9d4a-ba5f171f4d92","elapsed_milliseconds":3560,"source":"migration_from_base_and_back"}
2302024-12-04T00:59:02.942Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:03.359672303Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","target":"migration_from_base_and_back_lifecycle_0","source_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":3957,"source":"migration_from_base_and_back"}
2312024-12-04T00:59:02.942Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:03.360835708Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2322024-12-04T00:59:02.942Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:03.361015883Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2332024-12-04T00:59:02.942Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:03.361069024Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2342024-12-04T00:59:02.942Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:03.361684702Z","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":"0f12f658-3236-4169-bf72-0ddaf2a1b396","vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2352024-12-04T00:59:03.051Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:03.491402928Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":130,"vm":"migration_from_base_and_back","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"0f12f658-3236-4169-bf72-0ddaf2a1b396"}
2362024-12-04T00:59:05.432Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.872402801Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":2511,"vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119"}
2372024-12-04T00:59:05.455Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.872667809Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2382024-12-04T00:59:05.455Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.87272483Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2392024-12-04T00:59:05.480Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.90577232Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119"}
2402024-12-04T00:59:05.480Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.905924624Z","target":"phd_framework::lifecycle","line":74,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base_and_back","propolis_artifact":"__BASE_PROPOLIS","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2412024-12-04T00:59:05.480Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.906050058Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2422024-12-04T00:59:05.480Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.90613792Z","target":"phd_framework::test_vm","line":206,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_name":"migration_from_base_and_back_lifecycle_1","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__BASE_PROPOLIS\" }","guest_os_kind":"Alpine","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2432024-12-04T00:59:05.480Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.906250454Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/7127f9a0268259da63364fdec667cb5b2b55048ae29e6461766495d1b90af32d/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2442024-12-04T00:59:05.480Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.906385067Z","target":"phd_framework::test_vm::server","line":55,"file":"phd-tests/framework/src/test_vm/server.rs","server_path":"\"/phd-artifacts/7127f9a0268259da63364fdec667cb5b2b55048ae29e6461766495d1b90af32d/propolis-server\"","config_toml_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.config.toml\"","server_addr":"127.0.0.1:9004","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2452024-12-04T00:59:05.480Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.90645985Z","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_1.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2462024-12-04T00:59:05.504Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 870","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.920935734Z","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"}
2472024-12-04T00:59:05.504Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.921227453Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":15,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2482024-12-04T00:59:05.504Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.921368887Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target":"migration_from_base_and_back_lifecycle_1","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0"}
2492024-12-04T00:59:05.504Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9002","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.92145182Z","target":"phd_framework::test_vm","line":573,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"7e7a082c-ae01-4803-8454-b9a71bfdd616","timeout_duration":"45s","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target":"migration_from_base_and_back_lifecycle_1","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0"}
2502024-12-04T00:59:05.504Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.921547762Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target":"migration_from_base_and_back_lifecycle_1","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","source":"migration_from_base_and_back_lifecycle_0"}
2512024-12-04T00:59:05.504Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:05.922067478Z","target":"phd_framework::test_vm","line":370,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9004/instance/spec)","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target":"migration_from_base_and_back_lifecycle_1","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","source":"migration_from_base_and_back_lifecycle_0"}
2522024-12-04T00:59:05.887Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:06.327550741Z","target":"phd_framework::test_vm","line":429,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: faf445f0-0a7c-495a-a5c4-4424e0ed2edb, metadata: InstanceMetadata { project_id: fac095b3-05e9-4ca7-bd03-55c4bca56e74, silo_id: b1f49f1e-5020-48d0-83f6-bd4235504827, sled_id: 0ca1197d-79cb-4c80-b490-f932dede7443, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"0ca1197d-79cb-4c80-b490-f932dede7443\" }, name: \"phd-vm-faf445f0-0a7c-495a-a5c4-4424e0ed2edb\" }, state: Migrating }","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target":"migration_from_base_and_back_lifecycle_1","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","source":"migration_from_base_and_back_lifecycle_0"}
2532024-12-04T00:59:05.911Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:06.327672155Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_1","vm":"migration_from_base_and_back_lifecycle_1","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","source":"migration_from_base_and_back_lifecycle_0","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":406}
2542024-12-04T00:59:05.911Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:06.327732657Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target":"migration_from_base_and_back_lifecycle_1","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"7e7a082c-ae01-4803-8454-b9a71bfdd616","source":"migration_from_base_and_back_lifecycle_0"}
2552024-12-04T00:59:08.382Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:08.822685372Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9004\",\"from_start\":7807}}"}
2562024-12-04T00:59:08.808Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.248840863Z","target":"phd_framework::test_vm","line":607,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target":"migration_from_base_and_back_lifecycle_1","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_0"}
2572024-12-04T00:59:08.808Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.248887954Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target":"migration_from_base_and_back_lifecycle_1","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"7e7a082c-ae01-4803-8454-b9a71bfdd616","elapsed_milliseconds":2921,"source":"migration_from_base_and_back_lifecycle_0"}
2582024-12-04T00:59:08.831Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.248929935Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","target":"migration_from_base_and_back_lifecycle_1","source_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":3327,"source":"migration_from_base_and_back_lifecycle_0"}
2592024-12-04T00:59:08.831Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.250490621Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2602024-12-04T00:59:08.831Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.250664976Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2612024-12-04T00:59:08.831Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.250717958Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"ls foo.bar","timeout_duration":"Explicit(15s)","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2622024-12-04T00:59:08.832Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.251229693Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119","vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2632024-12-04T00:59:08.949Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.369404569Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":118,"vm":"migration_from_base_and_back_lifecycle_0","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1ce07b8a-b6dc-4bf6-b790-60245b6d3119"}
2642024-12-04T00:59:09.272Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.712801752Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":462,"vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb"}
2652024-12-04T00:59:09.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.713085921Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2662024-12-04T00:59:09.295Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.713169853Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2672024-12-04T00:59:09.318Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.746198542Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":33,"vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb"}
2682024-12-04T00:59:09.318Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.746345206Z","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"}
2692024-12-04T00:59:09.318Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.74648409Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2702024-12-04T00:59:09.318Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.746578513Z","target":"phd_framework::test_vm","line":206,"file":"phd-tests/framework/src/test_vm/mod.rs","guest_os_kind":"Alpine","vm_name":"migration_from_base_and_back_lifecycle_2","environment":"EnvironmentSpec { location: Local, propolis_artifact: \"__DEFAULT_PROPOLIS\" }","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2712024-12-04T00:59:09.318Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.746687436Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/work/phd-test/propolis-server","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2722024-12-04T00:59:09.318Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.746792399Z","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_and_back_lifecycle_2.config.toml\"","server_path":"\"/work/phd-test/propolis-server\"","server_addr":"127.0.0.1:9006","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2732024-12-04T00:59:09.319Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.74683226Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stderr_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log\"","stdout_path":"\"/tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log\"","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2742024-12-04T00:59:09.341Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 872","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.763030506Z","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"}
2752024-12-04T00:59:09.341Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.763242682Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":16,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2762024-12-04T00:59:09.341Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.763334675Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target":"migration_from_base_and_back_lifecycle_2","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1"}
2772024-12-04T00:59:09.341Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9004","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.763390716Z","target":"phd_framework::test_vm","line":573,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"2ef9fd1b-da99-4afa-ac0c-f437386929df","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target":"migration_from_base_and_back_lifecycle_2","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1"}
2782024-12-04T00:59:09.341Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.763454648Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target":"migration_from_base_and_back_lifecycle_2","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","source":"migration_from_base_and_back_lifecycle_1"}
2792024-12-04T00:59:09.342Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:09.764016075Z","target":"phd_framework::test_vm","line":370,"file":"phd-tests/framework/src/test_vm/mod.rs","e":"Communication Error: error sending request for url (http://127.0.0.1:9006/instance/spec)","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target":"migration_from_base_and_back_lifecycle_2","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","source":"migration_from_base_and_back_lifecycle_1"}
2802024-12-04T00:59:10.072Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:10.513041166Z","target":"phd_framework::test_vm","line":429,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 1ff1f77e-4c9d-4973-82a3-a401300ac0a4, metadata: InstanceMetadata { project_id: fac095b3-05e9-4ca7-bd03-55c4bca56e74, silo_id: b1f49f1e-5020-48d0-83f6-bd4235504827, sled_id: 27a8f650-8dbb-4dfb-8e8a-5fdcae66fdfb, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"27a8f650-8dbb-4dfb-8e8a-5fdcae66fdfb\" }, name: \"phd-vm-1ff1f77e-4c9d-4973-82a3-a401300ac0a4\" }, state: Migrating }","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target":"migration_from_base_and_back_lifecycle_2","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","source":"migration_from_base_and_back_lifecycle_1"}
2812024-12-04T00:59:10.095Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:10.513139288Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_from_base_and_back_lifecycle_2","vm":"migration_from_base_and_back_lifecycle_2","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","source":"migration_from_base_and_back_lifecycle_1","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":749}
2822024-12-04T00:59:10.095Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:10.51319013Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target":"migration_from_base_and_back_lifecycle_2","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"2ef9fd1b-da99-4afa-ac0c-f437386929df","source":"migration_from_base_and_back_lifecycle_1"}
2832024-12-04T00:59:12.639Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:13.079382054Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9006\",\"from_start\":7854}}"}
2842024-12-04T00:59:14.039Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.48001499Z","target":"phd_framework::test_vm","line":607,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target":"migration_from_base_and_back_lifecycle_2","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","source":"migration_from_base_and_back_lifecycle_1"}
2852024-12-04T00:59:14.062Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.480083682Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target":"migration_from_base_and_back_lifecycle_2","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","migration_id":"2ef9fd1b-da99-4afa-ac0c-f437386929df","elapsed_milliseconds":3966,"source":"migration_from_base_and_back_lifecycle_1"}
2862024-12-04T00:59:14.062Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.480131583Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","target_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","target":"migration_from_base_and_back_lifecycle_2","source_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","path":"phd_tests::migrate::from_base::migration_from_base_and_back","elapsed_milliseconds":4716,"source":"migration_from_base_and_back_lifecycle_1"}
2872024-12-04T00:59:14.064Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.481344879Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2882024-12-04T00:59:14.064Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.481551605Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2892024-12-04T00:59:14.064Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.481597996Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2902024-12-04T00:59:14.064Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.482171933Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9004","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb","vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2912024-12-04T00:59:14.168Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.609079166Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":127,"vm":"migration_from_base_and_back_lifecycle_1","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"faf445f0-0a7c-495a-a5c4-4424e0ed2edb"}
2922024-12-04T00:59:14.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.609704184Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":128,"vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4"}
2932024-12-04T00:59:14.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.609943631Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2942024-12-04T00:59:14.191Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.609991132Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2952024-12-04T00:59:14.215Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.63274017Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":22,"vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4"}
2962024-12-04T00:59:14.215Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.632884694Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
2972024-12-04T00:59:14.215Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.633057619Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
2982024-12-04T00:59:14.215Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.633188693Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":19652}
2992024-12-04T00:59:14.215Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::migration_from_base_and_back ... ok","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.633186543Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3002024-12-04T00:59:14.215Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.633264375Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3012024-12-04T00:59:14.215Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.633668757Z","target":"phd_framework::test_vm","line":1058,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3022024-12-04T00:59:14.491Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:14.932511033Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9006","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3032024-12-04T00:59:14.615Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.055791248Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3042024-12-04T00:59:14.637Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.055883621Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts/phd-clone-399e408c-32ef-44a8-b661-9e7fb2a503e2\"]","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3052024-12-04T00:59:14.661Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.090324521Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3062024-12-04T00:59:14.661Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.090378523Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"destroy","args":"[\"phd-artifacts@phd-cc155ee9-5e5c-4889-8393-0d2dabdf73f7\"]","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4","vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3072024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.118601861Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":485,"vm":"migration_from_base_and_back_lifecycle_2","path":"phd_tests::migrate::from_base::migration_from_base_and_back","vm_id":"1ff1f77e-4c9d-4973-82a3-a401300ac0a4"}
3082024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.118648142Z","target":"phd_tests::migrate::from_base","line":52,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":84939,"path":"phd_tests::migrate::from_base::migration_from_base_and_back"}
3092024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.118874519Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":485}
3102024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::serial_history","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.118930311Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3112024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.118957101Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
3122024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.118984422Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
3132024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.119158357Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::serial_history"}
3142024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.11924239Z","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"}
3152024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.119398184Z","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"}
3162024-12-04T00:59:14.684Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.119446496Z","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"}
3172024-12-04T00:59:14.685Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.119489907Z","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"}
3182024-12-04T00:59:14.708Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.138524135Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 693M 1.80T 693M /phd-artifacts\n","path":"phd_tests::migrate::from_base::serial_history"}
3192024-12-04T00:59:14.708Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.13867228Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"snapshot","args":"[\"phd-artifacts@phd-eaa12c2b-3862-431f-a5c9-a655b681bc32\"]","path":"phd_tests::migrate::from_base::serial_history"}
3202024-12-04T00:59:14.731Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.159888322Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-eaa12c2b-3862-431f-a5c9-a655b681bc32\", \"phd-artifacts/phd-clone-45088c75-79ba-4309-850e-aee341161fc6\"]","path":"phd_tests::migrate::from_base::serial_history"}
3212024-12-04T00:59:14.754Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.181588209Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-45088c75-79ba-4309-850e-aee341161fc6\"]","verb":"list","path":"phd_tests::migrate::from_base::serial_history"}
3222024-12-04T00:59:14.777Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.198558547Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-45088c75-79ba-4309-850e-aee341161fc6 0B 1.80T 693M /phd-artifacts/phd-clone-45088c75-79ba-4309-850e-aee341161fc6\n","path":"phd_tests::migrate::from_base::serial_history"}
3232024-12-04T00:59:14.777Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.199202165Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3242024-12-04T00:59:14.777Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.199257397Z","target":"phd_framework::test_vm","line":206,"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"}
3252024-12-04T00:59:14.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.199309029Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/7127f9a0268259da63364fdec667cb5b2b55048ae29e6461766495d1b90af32d/propolis-server","path":"phd_tests::migrate::from_base::serial_history"}
3262024-12-04T00:59:14.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.199386151Z","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_addr":"127.0.0.1:9000","server_path":"\"/phd-artifacts/7127f9a0268259da63364fdec667cb5b2b55048ae29e6461766495d1b90af32d/propolis-server\"","path":"phd_tests::migrate::from_base::serial_history"}
3272024-12-04T00:59:14.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.199425342Z","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"}
3282024-12-04T00:59:14.778Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 881","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.210697623Z","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"}
3292024-12-04T00:59:14.778Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.210981851Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":11,"path":"phd_tests::migrate::from_base::serial_history"}
3302024-12-04T00:59:14.778Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.211066453Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3312024-12-04T00:59:14.778Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:15.211576018Z","target":"phd_framework::test_vm","line":370,"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)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3322024-12-04T00:59:15.634Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.074623764Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
3332024-12-04T00:59:15.678Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.07518514Z","target":"phd_framework::test_vm","line":429,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: dc23be4a-856f-4f92-989a-edac8a502174, metadata: InstanceMetadata { project_id: 73d0cb6b-7c94-411e-ada8-1061c44fe958, silo_id: c8ce3046-6f40-4be1-bbc9-e73c14c8808a, sled_id: 381eaf80-e300-42bf-8742-a827a6ff0439, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"381eaf80-e300-42bf-8742-a827a6ff0439\" }, name: \"phd-vm-dc23be4a-856f-4f92-989a-edac8a502174\" }, state: Creating }","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3342024-12-04T00:59:15.678Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.075248772Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":864,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3352024-12-04T00:59:15.678Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.075309454Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3362024-12-04T00:59:15.678Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.075344875Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3372024-12-04T00:59:15.679Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.075880111Z","target":"phd_framework::test_vm","line":506,"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":"dc23be4a-856f-4f92-989a-edac8a502174"}
3382024-12-04T00:59:15.679Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.075937052Z","target":"phd_framework::test_vm","line":763,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3392024-12-04T00:59:15.679Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.075979114Z","target":"phd_framework::test_vm","line":712,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174","timeout_duration":"300s","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history"}
3402024-12-04T00:59:15.679Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.076012185Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::serial_history"}
3412024-12-04T00:59:15.679Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.076042786Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3422024-12-04T00:59:15.679Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:16.076074056Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3432024-12-04T00:59:19.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.256893964Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4180,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3442024-12-04T00:59:19.816Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.256967836Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::serial_history"}
3452024-12-04T00:59:19.839Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.257135371Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3462024-12-04T00:59:19.839Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.257182742Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3472024-12-04T00:59:19.840Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.257218083Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3482024-12-04T00:59:19.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.276042435Z","target":"phd_framework::test_vm","line":778,"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":"dc23be4a-856f-4f92-989a-edac8a502174"}
3492024-12-04T00:59:19.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.276165619Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::serial_history"}
3502024-12-04T00:59:19.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.276483308Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::serial_history"}
3512024-12-04T00:59:19.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.2765355Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3522024-12-04T00:59:19.841Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.276573791Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3532024-12-04T00:59:19.867Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.308367933Z","target":"phd_framework::test_vm","line":778,"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":"dc23be4a-856f-4f92-989a-edac8a502174"}
3542024-12-04T00:59:19.892Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.308459846Z","target":"phd_framework::test_vm","line":760,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3552024-12-04T00:59:19.892Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.308526238Z","target":"phd_framework::test_vm","line":763,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":4232,"path":"phd_tests::migrate::from_base::serial_history"}
3562024-12-04T00:59:19.892Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.308779715Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3572024-12-04T00:59:19.892Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.308875768Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"echo hello from the source VM!","timeout_duration":"Explicit(15s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3582024-12-04T00:59:19.892Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.319261003Z","target":"phd_framework::test_vm","line":778,"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":"dc23be4a-856f-4f92-989a-edac8a502174"}
3592024-12-04T00:59:19.892Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.31949213Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3602024-12-04T00:59:19.892Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.319570962Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3612024-12-04T00:59:19.915Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.352448307Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":32,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3622024-12-04T00:59:19.939Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.357083503Z","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"}
3632024-12-04T00:59:19.939Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.357151605Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::serial_history"}
3642024-12-04T00:59:19.939Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.357190226Z","target":"phd_framework::test_vm","line":206,"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"}
3652024-12-04T00:59:19.939Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.357239617Z","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"}
3662024-12-04T00:59:19.939Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.357311319Z","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"}
3672024-12-04T00:59:19.939Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.35735044Z","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"}
3682024-12-04T00:59:19.939Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 882","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.372831654Z","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"}
3692024-12-04T00:59:19.940Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.373041411Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":15,"path":"phd_tests::migrate::from_base::serial_history"}
3702024-12-04T00:59:19.940Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.373162924Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base"}
3712024-12-04T00:59:19.940Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.373249397Z","target":"phd_framework::test_vm","line":573,"file":"phd-tests/framework/src/test_vm/mod.rs","migration_id":"861a97d3-dcd5-44b7-ac9c-e5cf09e13f7e","timeout_duration":"45s","target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base"}
3722024-12-04T00:59:19.940Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.373344019Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base"}
3732024-12-04T00:59:19.940Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:20.37405491Z","target":"phd_framework::test_vm","line":370,"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)","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base"}
3742024-12-04T00:59:20.748Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:21.188887442Z","target":"phd_framework::test_vm","line":429,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 752639e5-4ceb-48a7-a4aa-aeb842317041, metadata: InstanceMetadata { project_id: 73d0cb6b-7c94-411e-ada8-1061c44fe958, silo_id: c8ce3046-6f40-4be1-bbc9-e73c14c8808a, sled_id: a6e8d287-d907-47b3-a3f9-72bb7488aa24, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"a6e8d287-d907-47b3-a3f9-72bb7488aa24\" }, name: \"phd-vm-752639e5-4ceb-48a7-a4aa-aeb842317041\" }, state: Migrating }","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base"}
3752024-12-04T00:59:20.772Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:21.188985665Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","elapsed_milliseconds":815,"source":"migration_serial_history_base","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history"}
3762024-12-04T00:59:20.772Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:21.189042936Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","migration_id":"861a97d3-dcd5-44b7-ac9c-e5cf09e13f7e","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base"}
3772024-12-04T00:59:23.296Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:23.736975446Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7727}}"}
3782024-12-04T00:59:24.727Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.168340902Z","target":"phd_framework::test_vm","line":607,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base"}
3792024-12-04T00:59:24.751Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.168450335Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":3979,"target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","migration_id":"861a97d3-dcd5-44b7-ac9c-e5cf09e13f7e","path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base"}
3802024-12-04T00:59:24.751Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.168549418Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"migration_serial_history_base_lifecycle_0","source_id":"dc23be4a-856f-4f92-989a-edac8a502174","target_id":"752639e5-4ceb-48a7-a4aa-aeb842317041","elapsed_milliseconds":4795,"path":"phd_tests::migrate::from_base::serial_history","source":"migration_serial_history_base"}
3812024-12-04T00:59:24.751Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.16998958Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3822024-12-04T00:59:24.751Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.170806264Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3832024-12-04T00:59:24.863Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.303934069Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":133,"vm":"migration_serial_history_base","path":"phd_tests::migrate::from_base::serial_history","vm_id":"dc23be4a-856f-4f92-989a-edac8a502174"}
3842024-12-04T00:59:24.886Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.306701611Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041"}
3852024-12-04T00:59:24.886Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.306877846Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
3862024-12-04T00:59:24.886Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.30701727Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9232}
3872024-12-04T00:59:24.886Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::serial_history ... ok","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.30701423Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
3882024-12-04T00:59:24.886Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.307101662Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
3892024-12-04T00:59:24.886Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.307601407Z","target":"phd_framework::test_vm","line":1058,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041"}
3902024-12-04T00:59:25.228Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.6687161Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041"}
3912024-12-04T00:59:25.363Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.803846924Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041"}
3922024-12-04T00:59:25.386Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.803942926Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-45088c75-79ba-4309-850e-aee341161fc6\"]","verb":"destroy","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041"}
3932024-12-04T00:59:25.409Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.83543622Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041"}
3942024-12-04T00:59:25.409Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.835487182Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-eaa12c2b-3862-431f-a5c9-a655b681bc32\"]","verb":"destroy","vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041"}
3952024-12-04T00:59:25.432Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.862809023Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","elapsed_milliseconds":555,"vm":"migration_serial_history_base_lifecycle_0","path":"phd_tests::migrate::from_base::serial_history","vm_id":"752639e5-4ceb-48a7-a4aa-aeb842317041"}
3962024-12-04T00:59:25.432Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.862851045Z","target":"phd_tests::migrate::from_base","line":40,"file":"phd-tests/tests/src/migrate.rs","elapsed_milliseconds":10743,"path":"phd_tests::migrate::from_base::serial_history"}
3972024-12-04T00:59:25.432Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.863067811Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":555}
3982024-12-04T00:59:25.432Z{"v":0,"name":"phd-runner","msg":"Starting test phd_tests::migrate::from_base::can_migrate_from_base","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.863132593Z","target":"phd_runner::execute","line":90,"file":"phd-tests/runner/src/execute.rs"}
3992024-12-04T00:59:25.432Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.863161794Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs"}
4002024-12-04T00:59:25.432Z{"v":0,"name":"phd-runner","msg":"[TEST_SETUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.863190784Z","target":"phd_runner::fixtures","line":41,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
4012024-12-04T00:59:25.432Z{"v":0,"name":"phd-runner","msg":"[TEST - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.86335904Z","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"}
4022024-12-04T00:59:25.432Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.863438082Z","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"}
4032024-12-04T00:59:25.432Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.863596287Z","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"}
4042024-12-04T00:59:25.433Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.863644748Z","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"}
4052024-12-04T00:59:25.433Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.863689759Z","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"}
4062024-12-04T00:59:25.457Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.881673847Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts 694M 1.80T 693M /phd-artifacts\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4072024-12-04T00:59:25.457Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.88177673Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-234b8fd0-8047-47b9-b1f6-2e0f0f9991a6\"]","verb":"snapshot","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4082024-12-04T00:59:25.480Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.903168527Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"clone","args":"[\"phd-artifacts@phd-234b8fd0-8047-47b9-b1f6-2e0f0f9991a6\", \"phd-artifacts/phd-clone-cccacc21-66e9-4e66-98c6-1fb3ad538fa8\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4092024-12-04T00:59:25.503Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.927496361Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","verb":"list","args":"[\"phd-artifacts/phd-clone-cccacc21-66e9-4e66-98c6-1fb3ad538fa8\"]","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4102024-12-04T00:59:25.503Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] parsing zfs list output","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.943761378Z","target":"phd_framework::zfs","line":238,"file":"phd-tests/framework/src/zfs.rs","stdout":"NAME USED AVAIL REFER MOUNTPOINT\nphd-artifacts/phd-clone-cccacc21-66e9-4e66-98c6-1fb3ad538fa8 0B 1.80T 693M /phd-artifacts/phd-clone-cccacc21-66e9-4e66-98c6-1fb3ad538fa8\n","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4112024-12-04T00:59:25.527Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.944357956Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4122024-12-04T00:59:25.527Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.944415837Z","target":"phd_framework::test_vm","line":206,"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","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4132024-12-04T00:59:25.527Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.944463439Z","target":"phd_framework::artifacts::store","line":45,"file":"phd-tests/framework/src/artifacts/store.rs","path":"/phd-artifacts/7127f9a0268259da63364fdec667cb5b2b55048ae29e6461766495d1b90af32d/propolis-server","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4142024-12-04T00:59:25.527Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.944536721Z","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.config.toml\"","server_path":"\"/phd-artifacts/7127f9a0268259da63364fdec667cb5b2b55048ae29e6461766495d1b90af32d/propolis-server\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4152024-12-04T00:59:25.527Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.944574582Z","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"}
4162024-12-04T00:59:25.527Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 891","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.954463142Z","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"}
4172024-12-04T00:59:25.527Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.954645027Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10}
4182024-12-04T00:59:25.529Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.95472484Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4192024-12-04T00:59:25.529Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:25.955219654Z","target":"phd_framework::test_vm","line":370,"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)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4202024-12-04T00:59:25.894Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.334935812Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs"}
4212024-12-04T00:59:25.917Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.335696524Z","target":"phd_framework::test_vm","line":429,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 9db8982f-b516-48ee-8393-8b521ba04492, metadata: InstanceMetadata { project_id: 03e415b0-de57-485a-b177-431209c2fbc1, silo_id: 492f0772-2f1d-445a-ac2d-549b0b7e0d58, sled_id: e9b2e859-3388-49ac-8557-cd2ebda64f64, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"e9b2e859-3388-49ac-8557-cd2ebda64f64\" }, name: \"phd-vm-9db8982f-b516-48ee-8393-8b521ba04492\" }, state: Creating }","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4222024-12-04T00:59:25.917Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.335760506Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":380,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4232024-12-04T00:59:25.917Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.335819758Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4242024-12-04T00:59:25.917Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - EVENT] Requesting instance state change","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.335858169Z","target":"phd_framework::test_vm","line":511,"file":"phd-tests/framework/src/test_vm/mod.rs","state":"Run","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4252024-12-04T00:59:25.918Z{"v":0,"name":"phd-runner","msg":"[PUT_INSTANCE_STATE - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.336397335Z","target":"phd_framework::test_vm","line":506,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":0,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4262024-12-04T00:59:25.918Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.336456137Z","target":"phd_framework::test_vm","line":763,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4272024-12-04T00:59:25.918Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] waiting for guest to boot","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.336497098Z","target":"phd_framework::test_vm","line":712,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492","timeout_duration":"300s","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4282024-12-04T00:59:25.918Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.336529249Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost login: \")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4292024-12-04T00:59:25.918Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.33656032Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4302024-12-04T00:59:25.918Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:26.336597011Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"CallerTimeout","target":"localhost login: ","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4312024-12-04T00:59:30.121Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.561618704Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4225,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4322024-12-04T00:59:30.121Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.561692466Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"root\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4332024-12-04T00:59:30.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.561911853Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4342024-12-04T00:59:30.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.561959985Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4352024-12-04T00:59:30.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.561995115Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4362024-12-04T00:59:30.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.58091273Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":18,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4372024-12-04T00:59:30.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.581052134Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WriteStr(\"stty -F `tty` cols 9999\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4382024-12-04T00:59:30.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] executing command in boot sequence","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.581404475Z","target":"phd_framework::test_vm","line":720,"file":"phd-tests/framework/src/test_vm/mod.rs","step":"WaitFor(\"localhost:~#\")","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4392024-12-04T00:59:30.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.581515268Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4402024-12-04T00:59:30.144Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.581602171Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"CallerTimeout","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4412024-12-04T00:59:30.173Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.614253488Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4422024-12-04T00:59:30.196Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - EVENT] Guest has booted","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.614342491Z","target":"phd_framework::test_vm","line":760,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4432024-12-04T00:59:30.196Z{"v":0,"name":"phd-runner","msg":"[WAIT_TO_BOOT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.614404673Z","target":"phd_framework::test_vm","line":763,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":4277}
4442024-12-04T00:59:30.196Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.61464082Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4452024-12-04T00:59:30.196Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.614735222Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar 2> /dev/null","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4462024-12-04T00:59:30.196Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.625142068Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4472024-12-04T00:59:30.196Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.625357774Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4482024-12-04T00:59:30.196Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.625436056Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4492024-12-04T00:59:30.220Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.658366973Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4502024-12-04T00:59:30.220Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.65861302Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4512024-12-04T00:59:30.220Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.658705072Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"touch ./foo.bar","timeout_duration":"Explicit(15s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4522024-12-04T00:59:30.243Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.669127608Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4532024-12-04T00:59:30.243Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.669366965Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4542024-12-04T00:59:30.243Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.669446838Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4552024-12-04T00:59:30.266Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.702347252Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4562024-12-04T00:59:30.268Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.70261492Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4572024-12-04T00:59:30.268Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.702705533Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"sync ./foo.bar","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4582024-12-04T00:59:30.292Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.71316253Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4592024-12-04T00:59:30.292Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.713374986Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4602024-12-04T00:59:30.292Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.713454128Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(300s)","target":"localhost:~#","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4612024-12-04T00:59:30.315Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.735018311Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":21,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4622024-12-04T00:59:30.315Z{"v":0,"name":"phd-runner","msg":"[TEST - EVENT] migrating to new Propolis artifact for lifecycle test","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.735080753Z","target":"phd_framework::lifecycle","line":74,"file":"phd-tests/framework/src/lifecycle.rs","vm_name":"migration_from_base","propolis_artifact":"__DEFAULT_PROPOLIS","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4632024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[NEW - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.735137244Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4642024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] phd_framework::test_vm","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.735185946Z","target":"phd_framework::test_vm","line":206,"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"}
4652024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Verified artifact already exists","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.735243217Z","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"}
4662024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launching Propolis server","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.73532666Z","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"}
4672024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Opening server log files","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.735371261Z","target":"phd_framework::server_log_mode","line":64,"file":"phd-tests/framework/src/server_log_mode.rs","stdout_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log\"","stderr_path":"\"/tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log\"","path":"phd_tests::migrate::from_base::can_migrate_from_base"}
4682024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[NEW - EVENT] Launched server with pid 892","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.749859676Z","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"}
4692024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[NEW - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.750061272Z","target":"phd_framework::test_vm","line":188,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":14}
4702024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.750144835Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","target":"migration_from_base_lifecycle_0","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","source":"migration_from_base"}
4712024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migrating from source at address 127.0.0.1:9000","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.750202136Z","target":"phd_framework::test_vm","line":573,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"45s","migration_id":"e7b7bff1-8d3d-411c-bc70-8266c720e282","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","target":"migration_from_base_lifecycle_0","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","source":"migration_from_base"}
4722024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.750266998Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","target":"migration_from_base_lifecycle_0","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","source":"migration_from_base"}
4732024-12-04T00:59:30.316Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] retriable error from instance_spec_ensure","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:30.750718822Z","target":"phd_framework::test_vm","line":370,"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)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","target":"migration_from_base_lifecycle_0","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","source":"migration_from_base"}
4742024-12-04T00:59:31.066Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - EVENT] Started instance","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:31.506857481Z","target":"phd_framework::test_vm","line":429,"file":"phd-tests/framework/src/test_vm/mod.rs","instance_description.instance":"Instance { properties: InstanceProperties { description: \"Pheidippides-managed VM\", id: 17c5e499-5d9a-4828-9553-dbf903e8af28, metadata: InstanceMetadata { project_id: 03e415b0-de57-485a-b177-431209c2fbc1, silo_id: 492f0772-2f1d-445a-ac2d-549b0b7e0d58, sled_id: 461f71fa-7d93-4d79-944b-816f4e8b59b1, sled_model: \"pheidippes\", sled_revision: 1, sled_serial: \"461f71fa-7d93-4d79-944b-816f4e8b59b1\" }, name: \"phd-vm-17c5e499-5d9a-4828-9553-dbf903e8af28\" }, state: Migrating }","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","target":"migration_from_base_lifecycle_0","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","source":"migration_from_base"}
4752024-12-04T00:59:31.089Z{"v":0,"name":"phd-runner","msg":"[INSTANCE_ENSURE_INTERNAL - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:31.506953684Z","target":"phd_framework::test_vm","line":292,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":756,"target":"migration_from_base_lifecycle_0","source":"migration_from_base","vm":"migration_from_base_lifecycle_0","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4762024-12-04T00:59:31.090Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:31.507002665Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","target":"migration_from_base_lifecycle_0","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","migration_id":"e7b7bff1-8d3d-411c-bc70-8266c720e282","source":"migration_from_base"}
4772024-12-04T00:59:33.611Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial socket control message","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:34.05206396Z","target":"phd_framework::serial","line":275,"file":"phd-tests/framework/src/serial/mod.rs","s":"{\"Migrating\":{\"destination\":\"127.0.0.1:9002\",\"from_start\":7760}}"}
4782024-12-04T00:59:35.408Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - EVENT] Migration completed successfully","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.84932229Z","target":"phd_framework::test_vm","line":607,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","target":"migration_from_base_lifecycle_0","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","source":"migration_from_base"}
4792024-12-04T00:59:35.408Z{"v":0,"name":"phd-runner","msg":"[MIGRATE - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.849373401Z","target":"phd_framework::test_vm","line":594,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","elapsed_milliseconds":4342,"target":"migration_from_base_lifecycle_0","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","migration_id":"e7b7bff1-8d3d-411c-bc70-8266c720e282","source":"migration_from_base"}
4802024-12-04T00:59:35.432Z{"v":0,"name":"phd-runner","msg":"[MIGRATE_FROM - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.849423663Z","target":"phd_framework::test_vm","line":540,"file":"phd-tests/framework/src/test_vm/mod.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","source_id":"9db8982f-b516-48ee-8393-8b521ba04492","elapsed_milliseconds":5099,"target":"migration_from_base_lifecycle_0","target_id":"17c5e499-5d9a-4828-9553-dbf903e8af28","source":"migration_from_base"}
4812024-12-04T00:59:35.432Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.85068669Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4822024-12-04T00:59:35.433Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.850913267Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4832024-12-04T00:59:35.433Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.850961398Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","timeout_duration":"Explicit(15s)","target":"ls foo.bar","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4842024-12-04T00:59:35.433Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.851588766Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9000","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4852024-12-04T00:59:35.539Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.979722444Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":128,"vm_id":"9db8982f-b516-48ee-8393-8b521ba04492"}
4862024-12-04T00:59:35.562Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.98027035Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":129,"vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4872024-12-04T00:59:35.562Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.980452066Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4882024-12-04T00:59:35.562Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - EVENT] Waiting for output on serial console","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:35.980513667Z","target":"phd_framework::test_vm","line":785,"file":"phd-tests/framework/src/test_vm/mod.rs","target":"localhost:~#","timeout_duration":"Explicit(300s)","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4892024-12-04T00:59:35.587Z{"v":0,"name":"phd-runner","msg":"[WAIT_FOR_SERIAL_OUTPUT - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.013356911Z","target":"phd_framework::test_vm","line":778,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":32,"vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4902024-12-04T00:59:35.587Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.013494495Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4912024-12-04T00:59:35.587Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - EVENT] serial console command channel was closed","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.013767973Z","target":"phd_framework::serial","line":213,"file":"phd-tests/framework/src/serial/mod.rs"}
4922024-12-04T00:59:35.587Z{"v":0,"name":"phd-runner","msg":"[SERIAL CONSOLE TASK - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.013860546Z","target":"phd_framework::serial","line":200,"file":"phd-tests/framework/src/serial/mod.rs","elapsed_milliseconds":9678}
4932024-12-04T00:59:35.587Z{"v":0,"name":"phd-runner","msg":"test phd_tests::migrate::from_base::can_migrate_from_base ... ok","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.013856125Z","target":"phd_runner::execute","line":129,"file":"phd-tests/runner/src/execute.rs"}
4942024-12-04T00:59:35.587Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.013952928Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs"}
4952024-12-04T00:59:35.587Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] trying to ensure Propolis server VM is destroyed","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.014673979Z","target":"phd_framework::test_vm","line":1058,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4962024-12-04T00:59:35.906Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] Killing Propolis server process","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.346871324Z","target":"phd_framework::test_vm::server","line":125,"file":"phd-tests/framework/src/test_vm/server.rs","self.address":"127.0.0.1:9002","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4972024-12-04T00:59:36.025Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs clone dropped","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.46606598Z","target":"phd_framework::zfs","line":83,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4982024-12-04T00:59:36.048Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.466163373Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts/phd-clone-cccacc21-66e9-4e66-98c6-1fb3ad538fa8\"]","verb":"destroy","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
4992024-12-04T00:59:36.071Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] zfs snapshot dropped","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.499909893Z","target":"phd_framework::zfs","line":57,"file":"phd-tests/framework/src/zfs.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
5002024-12-04T00:59:36.071Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - EVENT] executing ZFS command","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.499962315Z","target":"phd_framework::zfs","line":304,"file":"phd-tests/framework/src/zfs.rs","args":"[\"phd-artifacts@phd-234b8fd0-8047-47b9-b1f6-2e0f0f9991a6\"]","verb":"destroy","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
5012024-12-04T00:59:36.094Z{"v":0,"name":"phd-runner","msg":"[VM CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.525563786Z","target":"phd_framework::test_vm","line":1035,"file":"phd-tests/framework/src/test_vm/mod.rs","vm":"migration_from_base_lifecycle_0","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":511,"vm_id":"17c5e499-5d9a-4828-9553-dbf903e8af28"}
5022024-12-04T00:59:36.094Z{"v":0,"name":"phd-runner","msg":"[TEST - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.525604987Z","target":"phd_tests::migrate::from_base","line":34,"file":"phd-tests/tests/src/migrate.rs","path":"phd_tests::migrate::from_base::can_migrate_from_base","elapsed_milliseconds":10662}
5032024-12-04T00:59:36.094Z{"v":0,"name":"phd-runner","msg":"[TEST_CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.525843314Z","target":"phd_runner::fixtures","line":51,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":511}
5042024-12-04T00:59:36.094Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - START]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.525910316Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs"}
5052024-12-04T00:59:36.094Z{"v":0,"name":"phd-runner","msg":"[EXECUTION_CLEANUP - END]","level":30,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.525944907Z","target":"phd_runner::fixtures","line":35,"file":"phd-tests/runner/src/fixtures.rs","elapsed_milliseconds":0}
5062024-12-04T00:59:36.094Ztest result: ok. 3 passed; 0 failed; 0 skipped; 0 not run; finished in 106.35s
5072024-12-04T00:59:36.094Z
5082024-12-04T00:59:36.094Z{"v":0,"name":"phd-runner","msg":"phd_runner","level":20,"hostname":"sock","pid":862,"time":"2024-12-04T00:59:36.526021209Z","target":"phd_runner","line":40,"file":"phd-tests/runner/src/main.rs","exit_code":0}
5092024-12-04T00:59:36.162Z
5102024-12-04T00:59:36.186Zreal 1:47.063203720
5112024-12-04T00:59:36.186Zuser 38.170425900
5122024-12-04T00:59:36.186Zsys 15.478018785
5132024-12-04T00:59:36.186Ztrap 0.004347735
5142024-12-04T00:59:36.186Ztflt 0.001619633
5152024-12-04T00:59:36.186Zdflt 0.000355743
5162024-12-04T00:59:36.186Zkflt 0.000334185
5172024-12-04T00:59:36.186Zlock 1:45:26.283337394
5182024-12-04T00:59:36.186Zslp 4:36.070730638
5192024-12-04T00:59:36.186Zlat 0.331204329
5202024-12-04T00:59:36.186Zstop 16.305841342
5212024-12-04T00:59:36.186Z+ failcount=0
5222024-12-04T00:59:36.186Z+ set -e
5232024-12-04T00:59:36.186Z+ tar -czvf /tmp/phd-tmp-files.tar.gz -C /tmp/propolis-phd /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log /tmp/propolis-phd/migration_from_base_and_back.serial.log /tmp/propolis-phd/migration_from_base_and_back.stderr.log /tmp/propolis-phd/migration_from_base_and_back.stdout.log /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log /tmp/propolis-phd/migration_from_base.serial.log /tmp/propolis-phd/migration_from_base.stderr.log /tmp/propolis-phd/migration_from_base.stdout.log /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log /tmp/propolis-phd/migration_serial_history_base.serial.log /tmp/propolis-phd/migration_serial_history_base.stderr.log /tmp/propolis-phd/migration_serial_history_base.stdout.log -C /tmp/propolis-phd /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.config.toml /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.config.toml /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.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
5242024-12-04T00:59:36.186ZCompressing '/tmp/phd-tmp-files.tar.gz' with '/usr/bin/gzip'...
5252024-12-04T00:59:36.186Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stderr.log 0K
5262024-12-04T00:59:36.186Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.stdout.log 202K
5272024-12-04T00:59:36.186Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stderr.log 0K
5282024-12-04T00:59:36.187Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.stdout.log 202K
5292024-12-04T00:59:36.187Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stderr.log 0K
5302024-12-04T00:59:36.187Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.stdout.log 115K
5312024-12-04T00:59:36.187Za /tmp/propolis-phd/migration_from_base_and_back.serial.log 7K
5322024-12-04T00:59:36.187Za /tmp/propolis-phd/migration_from_base_and_back.stderr.log 0K
5332024-12-04T00:59:36.187Za /tmp/propolis-phd/migration_from_base_and_back.stdout.log 114K
5342024-12-04T00:59:36.187Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stderr.log 0K
5352024-12-04T00:59:36.187Za /tmp/propolis-phd/migration_from_base_lifecycle_0.stdout.log 114K
5362024-12-04T00:59:36.187Za /tmp/propolis-phd/migration_from_base.serial.log 7K
5372024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_from_base.stderr.log 0K
5382024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_from_base.stdout.log 113K
5392024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stderr.log 0K
5402024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.stdout.log 115K
5412024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_serial_history_base.serial.log 7K
5422024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_serial_history_base.stderr.log 0K
5432024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_serial_history_base.stdout.log 114K
5442024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_0.config.toml 1K
5452024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_1.config.toml 1K
5462024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_from_base_and_back_lifecycle_2.config.toml 1K
5472024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_from_base_and_back.config.toml 1K
5482024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_from_base_lifecycle_0.config.toml 1K
5492024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_from_base.config.toml 1K
5502024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_serial_history_base_lifecycle_0.config.toml 1K
5512024-12-04T00:59:36.188Za /tmp/propolis-phd/migration_serial_history_base.config.toml 1K
5522024-12-04T00:59:36.188Z+ exitcode=0
5532024-12-04T00:59:36.188Z+ '[' 0 -eq 0 ']'
5542024-12-04T00:59:36.188Z+ echo
5552024-12-04T00:59:36.188Z
5562024-12-04T00:59:36.188Z+ echo 'ALL TESTS PASSED'
5572024-12-04T00:59:36.188ZALL TESTS PASSED
5582024-12-04T00:59:36.188Z+ echo
5592024-12-04T00:59:36.188Z
5602024-12-04T00:59:36.188Z+ find /dev/vmm -mindepth 1 -maxdepth 1
5612024-12-04T00:59:36.188Z+ read
5622024-12-04T00:59:36.189Z+ exit 0
5632024-12-04T00:59:36.189Zprocess exited: duration 116528 ms, exit code 0
 
5642024-12-04T00:59:36.236Zfound 2 output files
5652024-12-04T00:59:36.236Zuploading: /tmp/phd-runner.log (162643 bytes)
5662024-12-04T00:59:37.393Zuploaded: /tmp/phd-runner.log
5672024-12-04T00:59:37.393Zuploading: /tmp/phd-tmp-files.tar.gz (85966 bytes)
5682024-12-04T00:59:38.588Zuploaded: /tmp/phd-tmp-files.tar.gz