01KS1RFKXT80KNCAA94JJBY5AQ: falcon

BasicConfig {
    output_rules: [],
    rust_toolchain: None,
    target: Some(
        "lab-2.0-gimlet",
    ),
    access_repos: [],
    publish: [],
    skip_clone: true,
}

Buildomat Job: 01KS1RGHMC479X5JA4EFMCAJH8

Tags:

Output:

SEQ GLOBAL TIME DETAILS
12026-05-20T04:13:13.821Zjob dependencies complete; ready to run (waiting for 15 m 28 s)
22026-05-20T04:16:28.498Zjob assigned to worker 01KS1SCX1VBV7NAYHHBWN29E6V [factory edgar, gimlet/BRM42220010/975] (queued for 3 m 14 s)
32026-05-20T04:16:29.096Zdownloading input: /input/build-interop/work/testbed.tar.gz
42026-05-20T04:16:47.545Zdownloaded input: /input/build-interop/work/testbed.tar.gz
52026-05-20T04:16:47.545Zdownloading input: /input/build-interop/work/dhcp-server
62026-05-20T04:16:51.217Zdownloaded input: /input/build-interop/work/dhcp-server
72026-05-20T04:16:51.462Zdownloading input: /input/build/work/debug/ddmadm
82026-05-20T04:17:50.679Zdownloaded input: /input/build/work/debug/ddmadm
92026-05-20T04:17:50.679Zdownloading input: /input/build/work/debug/ddmd
102026-05-20T04:20:00.414Zdownloaded input: /input/build/work/debug/ddmd
112026-05-20T04:20:00.414Zdownloading input: /input/build/work/debug/mgadm
122026-05-20T04:21:09.580Zdownloaded input: /input/build/work/debug/mgadm
132026-05-20T04:21:09.580Zdownloading input: /input/build/work/debug/mgd
142026-05-20T04:22:45.391Zdownloaded input: /input/build/work/debug/mgd
152026-05-20T04:22:45.432Zdownloading input: /input/build/work/release/ddmadm
162026-05-20T04:22:49.488Zdownloaded input: /input/build/work/release/ddmadm
172026-05-20T04:22:49.488Zdownloading input: /input/build/work/release/ddmd
182026-05-20T04:23:19.745Zdownloaded input: /input/build/work/release/ddmd
192026-05-20T04:23:19.745Zdownloading input: /input/build/work/release/falcon-lab
202026-05-20T04:23:50.151Zdownloaded input: /input/build/work/release/falcon-lab
212026-05-20T04:23:50.152Zdownloading input: /input/build/work/release/mgadm
222026-05-20T04:24:07.605Zdownloaded input: /input/build/work/release/mgadm
232026-05-20T04:24:07.605Zdownloading input: /input/build/work/release/mgd
242026-05-20T04:24:30.006Zdownloaded input: /input/build/work/release/mgd
 
252026-05-20T04:24:30.144Zstarting task 0: "setup"
262026-05-20T04:24:30.144Z++ uname -s
272026-05-20T04:24:30.145Z+ kern=SunOS
282026-05-20T04:24:30.145Z+ build_user=build
292026-05-20T04:24:30.145Z+ build_uid=12345
302026-05-20T04:24:30.145Z+ work_dir=/work
312026-05-20T04:24:30.145Z+ input_dir=/input
322026-05-20T04:24:30.145Z+ [[ 0 == 12345 ]]
332026-05-20T04:24:30.145Z+ case "$kern" in
342026-05-20T04:24:30.145Z+ groupadd -g 12345 build
352026-05-20T04:24:30.145Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
362026-05-20T04:24:32.041Z+ zfs create -o mountpoint=/work rpool/work
372026-05-20T04:24:32.145Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
382026-05-20T04:24:32.192Z+ home_fs=
392026-05-20T04:24:32.192Z+ [[ '' == autofs ]]
402026-05-20T04:24:32.192Z+ mkdir -p /home/build
412026-05-20T04:24:32.192Z+ chown build:build /home/build /work
422026-05-20T04:24:34.148Z+ chmod 0700 /home/build /work
432026-05-20T04:24:34.182Zprocess exited: duration 4150 ms, exit code 0
 
442026-05-20T04:24:34.269Zstarting task 1: "authentication"
452026-05-20T04:24:34.377Zprocess exited: duration 115 ms, exit code 0
 
462026-05-20T04:24:34.455Zstarting task 2: "build"
472026-05-20T04:24:34.514Z+ set -e
482026-05-20T04:24:34.515Z+ banner zpool
492026-05-20T04:24:34.515Z
502026-05-20T04:24:34.515Z ###### ##### #### #### #
512026-05-20T04:24:34.515Z # # # # # # # #
522026-05-20T04:24:34.515Z # # # # # # # #
532026-05-20T04:24:34.515Z # ##### # # # # #
542026-05-20T04:24:34.515Z # # # # # # #
552026-05-20T04:24:34.515Z ###### # #### #### ######
562026-05-20T04:24:34.515Z
572026-05-20T04:24:34.515Z++ pfexec diskinfo -pH
582026-05-20T04:24:34.515Z++ sort -k8 -n -r
592026-05-20T04:24:34.515Z++ head -1
602026-05-20T04:24:34.516Z++ awk '{print $2}'
612026-05-20T04:24:34.552Z+ DISK=c9t0014EE81000BC3B1d0
622026-05-20T04:24:34.552Z+ export DISK
632026-05-20T04:24:34.552Z+ pfexec zpool create -o ashift=12 -f cpool c9t0014EE81000BC3B1d0
642026-05-20T04:24:34.608Z+ pfexec zfs create -o mountpoint=/ci cpool/ci
652026-05-20T04:24:34.648Z++ curl -s http://catacomb.eng.oxide.computer:12346/trim-me
662026-05-20T04:24:34.784Z+ [[ true =~ true ]]
672026-05-20T04:24:34.785Z+ pfexec zpool trim cpool
682026-05-20T04:24:34.827Z++ zpool status -t cpool
692026-05-20T04:24:34.827Z+ [[ ! pool: cpool
702026-05-20T04:24:34.827Z state: ONLINE
712026-05-20T04:24:34.827Z scan: none requested
722026-05-20T04:24:34.827Zconfig:
732026-05-20T04:24:34.827Z
742026-05-20T04:24:34.827Z NAME STATE READ WRITE CKSUM
752026-05-20T04:24:34.827Z cpool ONLINE 0 0 0
762026-05-20T04:24:34.827Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (1% trimmed, started at May 20, 2026 at 04:24:34 AM UTC)
772026-05-20T04:24:34.827Z
782026-05-20T04:24:34.827Zerrors: No known data errors =~ 100% ]]
792026-05-20T04:24:34.827Z+ sleep 10
802026-05-20T04:24:44.856Z++ zpool status -t cpool
812026-05-20T04:24:44.905Z+ [[ ! pool: cpool
822026-05-20T04:24:44.905Z state: ONLINE
832026-05-20T04:24:44.905Z scan: none requested
842026-05-20T04:24:44.905Zconfig:
852026-05-20T04:24:44.905Z
862026-05-20T04:24:44.905Z NAME STATE READ WRITE CKSUM
872026-05-20T04:24:44.905Z cpool ONLINE 0 0 0
882026-05-20T04:24:44.905Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (69% trimmed, started at May 20, 2026 at 04:24:34 AM UTC)
892026-05-20T04:24:44.905Z
902026-05-20T04:24:44.905Zerrors: No known data errors =~ 100% ]]
912026-05-20T04:24:44.905Z+ sleep 10
922026-05-20T04:24:56.028Z++ zpool status -t cpool
932026-05-20T04:24:56.029Z+ [[ ! pool: cpool
942026-05-20T04:24:56.029Z state: ONLINE
952026-05-20T04:24:56.029Z scan: none requested
962026-05-20T04:24:56.029Zconfig:
972026-05-20T04:24:56.029Z
982026-05-20T04:24:56.029Z NAME STATE READ WRITE CKSUM
992026-05-20T04:24:56.029Z cpool ONLINE 0 0 0
1002026-05-20T04:24:56.029Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (100% trimmed, completed at May 20, 2026 at 04:24:49 AM UTC)
1012026-05-20T04:24:56.029Z
1022026-05-20T04:24:56.029Zerrors: No known data errors =~ 100% ]]
1032026-05-20T04:24:56.029Z+ pfexec chown 12345 /ci
1042026-05-20T04:24:56.029Z+ cd /ci
1052026-05-20T04:24:56.029Z+ export FALCON_DATASET=cpool/falcon
1062026-05-20T04:24:56.029Z+ FALCON_DATASET=cpool/falcon
1072026-05-20T04:24:56.029Z+ banner setup
1082026-05-20T04:24:56.029Z
1092026-05-20T04:24:56.029Z #### ###### ##### # # #####
1102026-05-20T04:24:56.029Z # # # # # # #
1112026-05-20T04:24:56.029Z #### ##### # # # # #
1122026-05-20T04:24:56.029Z # # # # # #####
1132026-05-20T04:24:56.029Z # # # # # # #
1142026-05-20T04:24:56.029Z #### ###### # #### #
1152026-05-20T04:24:56.029Z
1162026-05-20T04:24:56.029Z+ cp /input/build-interop/work/dhcp-server .
1172026-05-20T04:24:56.029Z+ cp /input/build/work/release/falcon-lab .
1182026-05-20T04:24:56.029Z+ cp /input/build/work/release/mgd .
1192026-05-20T04:24:56.029Z+ cp /input/build/work/release/ddmd .
1202026-05-20T04:24:56.029Z+ chmod +x dhcp-server falcon-lab mgd ddmd
1212026-05-20T04:24:56.029Z+ mkdir -p cargo-bay
1222026-05-20T04:24:56.029Z+ mv mgd cargo-bay/
1232026-05-20T04:24:56.029Z+ mv ddmd cargo-bay/
1242026-05-20T04:24:56.029Z+ export EXT_INTERFACE=igb0
1252026-05-20T04:24:56.030Z+ EXT_INTERFACE=igb0
1262026-05-20T04:24:56.030Z++ bmat address ls -f extra -Ho first
1272026-05-20T04:24:56.077Z+ first=10.151.6.164
1282026-05-20T04:24:56.077Z++ bmat address ls -f extra -Ho last
1292026-05-20T04:24:56.077Z+ last=10.151.6.227
1302026-05-20T04:24:56.077Z++ bmat address ls -f extra -Ho gateway
1312026-05-20T04:24:56.122Z+ gw=10.151.6.1
1322026-05-20T04:24:56.122Z++ ipadm show-addr igb0/dhcp -po ADDR
1332026-05-20T04:24:56.122Z++ sed 's#/.*##g'
1342026-05-20T04:24:56.122Z+ server=10.151.6.100
1352026-05-20T04:24:56.122Z+ RUST_LOG=debug
1362026-05-20T04:24:56.123Z+ pfexec ./falcon-lab run trio-unnumbered
1372026-05-20T04:24:56.123Z+ pfexec ./dhcp-server 10.151.6.164 10.151.6.227 10.151.6.1 10.151.6.100
1382026-05-20T04:24:56.162ZMay 20 04:24:56.112 DEBG using default route interface igb0
1392026-05-20T04:24:56.162ZMay 20 04:24:56.112 DEBG using default route interface igb0
1402026-05-20T04:24:56.162ZMay 20 04:24:56.112 DEBG using default route interface igb0
1412026-05-20T04:24:56.162ZMay 20 04:24:56.112 INFO launching runner: deployment(mgtriou) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
1422026-05-20T04:24:56.162ZMay 20 04:24:56.112 INFO starting preflight for deployment mgtriou
1432026-05-20T04:24:56.162ZMay 20 04:24:56.112 INFO propolis-server binary not found
1442026-05-20T04:24:56.162ZMay 20 04:24:56.112 INFO downloading propolis server rev 36f20be9bb4c3b362029237f5feb6377c982395f, writing to .falcon/bin/propolis-server
1452026-05-20T04:25:05.073ZMay 20 04:25:05.049 INFO ovmf fd not found
1462026-05-20T04:25:05.073ZMay 20 04:25:05.049 INFO downloading ovmf
1472026-05-20T04:25:20.233ZMay 20 04:25:20.052 WARN failed to get url https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/OVMF_CODE.fd: retrying in 1 second
1482026-05-20T04:25:22.028ZMay 20 04:25:22.002 INFO base image for helios-2.9 does not exist, attempting to install
1492026-05-20T04:25:22.028ZMay 20 04:25:22.002 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/helios-2.9_0.raw.xz
1502026-05-20T04:26:21.221ZMay 20 04:26:21.212 INFO extracting image to /tmp/helios-2.9_0.raw
1512026-05-20T04:26:55.357ZMay 20 04:26:55.103 INFO creating zvol cpool/falcon/img/helios-2.9 of size 4508880896
1522026-05-20T04:26:55.795ZMay 20 04:26:55.153 INFO copying image data to zvol
1532026-05-20T04:27:05.571ZMay 20 04:27:05.564 INFO creating zfs snapshot cpool/falcon/img/helios-2.9@base
1542026-05-20T04:27:10.312ZMay 20 04:27:10.303 INFO base image for debian-13.2 does not exist, attempting to install
1552026-05-20T04:27:10.312ZMay 20 04:27:10.303 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz
1562026-05-20T04:27:25.316ZMay 20 04:27:25.305 WARN failed to get url https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz: retrying in 1 second
1572026-05-20T04:27:57.105ZMay 20 04:27:56.764 INFO extracting image to /tmp/debian-13.2_0.raw
1582026-05-20T04:28:17.971ZMay 20 04:28:17.968 INFO creating zvol cpool/falcon/img/debian-13.2 of size 3221229568
1592026-05-20T04:28:18.012ZMay 20 04:28:17.992 INFO copying image data to zvol
1602026-05-20T04:28:25.083ZMay 20 04:28:25.073 INFO creating zfs snapshot cpool/falcon/img/debian-13.2@base
1612026-05-20T04:28:28.564ZMay 20 04:28:28.559 INFO base image for eos-4.35 does not exist, attempting to install
1622026-05-20T04:28:28.564ZMay 20 04:28:28.559 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz
1632026-05-20T04:28:43.574ZMay 20 04:28:43.559 WARN failed to get url https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz: retrying in 1 second
1642026-05-20T04:29:52.821ZMay 20 04:29:52.714 INFO extracting image to /tmp/eos-4.35_0.raw
1652026-05-20T04:31:16.228ZMay 20 04:31:16.214 INFO creating zvol cpool/falcon/img/eos-4.35 of size 21474840576
1662026-05-20T04:31:16.272ZMay 20 04:31:16.239 INFO copying image data to zvol
1672026-05-20T04:32:04.872ZMay 20 04:32:04.851 INFO creating zfs snapshot cpool/falcon/img/eos-4.35@base
1682026-05-20T04:32:08.346ZMay 20 04:32:08.319 INFO creating links
1692026-05-20T04:32:08.346ZMay 20 04:32:08.319 DEBG destroying link mgtriou_ox_sn_vnic0
1702026-05-20T04:32:08.417ZMay 20 04:32:08.319 DEBG destroying link mgtriou_ox_sn_sim0
1712026-05-20T04:32:08.417ZMay 20 04:32:08.319 INFO creating simnet link 'mgtriou_ox_sn_sim0'
1722026-05-20T04:32:08.417ZMay 20 04:32:08.321 INFO creating vnic link 'mgtriou_ox_sn_vnic0'
1732026-05-20T04:32:08.417ZMay 20 04:32:08.329 DEBG link pair created
1742026-05-20T04:32:08.417ZMay 20 04:32:08.329 DEBG destroying link mgtriou_cr1_vn_vnic0
1752026-05-20T04:32:08.417ZMay 20 04:32:08.329 DEBG destroying link mgtriou_cr1_vn_sim0
1762026-05-20T04:32:08.417ZMay 20 04:32:08.329 INFO creating simnet link 'mgtriou_cr1_vn_sim0'
1772026-05-20T04:32:08.417ZMay 20 04:32:08.330 INFO creating vnic link 'mgtriou_cr1_vn_vnic0'
1782026-05-20T04:32:08.417ZMay 20 04:32:08.337 DEBG link pair created
1792026-05-20T04:32:08.417ZMay 20 04:32:08.337 DEBG destroying link mgtriou_ox_sn_vnic1
1802026-05-20T04:32:08.417ZMay 20 04:32:08.337 DEBG destroying link mgtriou_ox_sn_sim1
1812026-05-20T04:32:08.417ZMay 20 04:32:08.337 INFO creating simnet link 'mgtriou_ox_sn_sim1'
1822026-05-20T04:32:08.417ZMay 20 04:32:08.338 INFO creating vnic link 'mgtriou_ox_sn_vnic1'
1832026-05-20T04:32:08.417ZMay 20 04:32:08.345 DEBG link pair created
1842026-05-20T04:32:08.417ZMay 20 04:32:08.345 DEBG destroying link mgtriou_cr2_vn_vnic0
1852026-05-20T04:32:08.417ZMay 20 04:32:08.345 DEBG destroying link mgtriou_cr2_vn_sim0
1862026-05-20T04:32:08.418ZMay 20 04:32:08.345 INFO creating simnet link 'mgtriou_cr2_vn_sim0'
1872026-05-20T04:32:08.418ZMay 20 04:32:08.346 INFO creating vnic link 'mgtriou_cr2_vn_vnic0'
1882026-05-20T04:32:08.418ZMay 20 04:32:08.353 DEBG link pair created
1892026-05-20T04:32:08.418ZMay 20 04:32:08.353 INFO creating external links
1902026-05-20T04:32:08.418ZMay 20 04:32:08.353 DEBG destroying external link mgtriou_ox_vn_vnic2
1912026-05-20T04:32:08.418ZMay 20 04:32:08.353 INFO creating external link mgtriou_ox_vn_vnic2
1922026-05-20T04:32:08.418ZMay 20 04:32:08.356 DEBG external link mgtriou_ox_vn_vnic2@igb0 created
1932026-05-20T04:32:08.418ZMay 20 04:32:08.356 DEBG destroying external link mgtriou_cr1_vn_vnic1
1942026-05-20T04:32:08.418ZMay 20 04:32:08.356 INFO creating external link mgtriou_cr1_vn_vnic1
1952026-05-20T04:32:08.418ZMay 20 04:32:08.358 DEBG external link mgtriou_cr1_vn_vnic1@igb0 created
1962026-05-20T04:32:08.418ZMay 20 04:32:08.358 DEBG destroying external link mgtriou_cr2_vn_vnic1
1972026-05-20T04:32:08.418ZMay 20 04:32:08.358 INFO creating external link mgtriou_cr2_vn_vnic1
1982026-05-20T04:32:08.418ZMay 20 04:32:08.359 DEBG external link mgtriou_cr2_vn_vnic1@igb0 created
1992026-05-20T04:32:08.418ZMay 20 04:32:08.359 INFO creating nodes
2002026-05-20T04:32:08.418ZMay 20 04:32:08.359 INFO ox: launching node
2012026-05-20T04:32:08.418ZMay 20 04:32:08.362 INFO cr1: launching node
2022026-05-20T04:32:08.453ZMay 20 04:32:08.363 INFO cr2: launching node
2032026-05-20T04:32:08.453ZMay 20 04:32:08.377 INFO launched instance ox with pid 839 on port 62509
2042026-05-20T04:32:08.453ZMay 20 04:32:08.378 INFO ox: instance ensure
2052026-05-20T04:32:08.453ZMay 20 04:32:08.378 INFO launched instance cr1 with pid 840 on port 62111
2062026-05-20T04:32:08.453ZMay 20 04:32:08.378 INFO cr1: instance ensure
2072026-05-20T04:32:08.453ZMay 20 04:32:08.389 INFO launched instance cr2 with pid 841 on port 58394
2082026-05-20T04:32:08.453ZMay 20 04:32:08.389 INFO cr2: instance ensure
2092026-05-20T04:32:10.800ZMay 20 04:32:10.784 INFO cr2: instance ensure completed after 0 retries
2102026-05-20T04:32:10.801ZMay 20 04:32:10.784 INFO cr2: instance run
2112026-05-20T04:32:10.839ZMay 20 04:32:10.784 DEBG [sc] cr2: starting
2122026-05-20T04:32:10.839ZMay 20 04:32:10.784 DEBG [sc] cr2: connecting to [::1]:58394
2132026-05-20T04:32:10.839ZMay 20 04:32:10.786 DEBG [sc] cr2 waiting for prompt
2142026-05-20T04:32:10.839ZMay 20 04:32:10.792 INFO ox: instance ensure completed after 0 retries
2152026-05-20T04:32:10.839ZMay 20 04:32:10.792 INFO ox: instance run
2162026-05-20T04:32:10.839ZMay 20 04:32:10.793 DEBG [sc] ox: starting
2172026-05-20T04:32:10.839ZMay 20 04:32:10.793 DEBG [sc] ox: connecting to [::1]:62509
2182026-05-20T04:32:10.839ZMay 20 04:32:10.794 DEBG [sc] ox waiting for prompt
2192026-05-20T04:32:10.941ZMay 20 04:32:10.892 INFO cr1: instance ensure completed after 0 retries
2202026-05-20T04:32:10.941ZMay 20 04:32:10.892 INFO cr1: instance run
2212026-05-20T04:32:10.985ZMay 20 04:32:10.893 DEBG [sc] cr1: starting
2222026-05-20T04:32:10.986ZMay 20 04:32:10.893 DEBG [sc] cr1: connecting to [::1]:62111
2232026-05-20T04:32:10.986ZMay 20 04:32:10.893 DEBG [sc] cr1 waiting for prompt
2242026-05-20T04:32:27.931ZMay 20 04:32:27.914 DEBG [sc] cr1: logging in
2252026-05-20T04:32:28.301ZMay 20 04:32:28.276 INFO cr1: mounting /opt/cargo-bay
2262026-05-20T04:32:28.301ZMay 20 04:32:28.276 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2272026-05-20T04:32:28.342ZMay 20 04:32:28.286 DEBG [sc] cr1: executing command `cd`
2282026-05-20T04:32:28.342ZMay 20 04:32:28.298 INFO cr1: finished mounting /opt/cargo-bay
2292026-05-20T04:32:28.342ZMay 20 04:32:28.298 DEBG [sc] cr1: executing command `hostname cr1`
2302026-05-20T04:32:28.342ZMay 20 04:32:28.308 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
2312026-05-20T04:32:28.383ZMay 20 04:32:28.319 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
2322026-05-20T04:32:28.383ZMay 20 04:32:28.330 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
2332026-05-20T04:32:28.383ZMay 20 04:32:28.341 INFO cr1: logging out
2342026-05-20T04:32:30.431ZMay 20 04:32:30.408 INFO cr1: logged out
2352026-05-20T04:32:31.040ZMay 20 04:32:31.022 DEBG [sc] ox: logging in
2362026-05-20T04:32:31.230ZMay 20 04:32:31.212 INFO ox: mounting /opt/cargo-bay
2372026-05-20T04:32:31.230ZMay 20 04:32:31.212 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2382026-05-20T04:32:32.281ZMay 20 04:32:32.260 DEBG [sc] ox: executing command `cd`
2392026-05-20T04:32:32.331ZMay 20 04:32:32.271 INFO ox: finished mounting /opt/cargo-bay
2402026-05-20T04:32:32.331ZMay 20 04:32:32.271 DEBG [sc] ox: executing command `hostname ox`
2412026-05-20T04:32:32.331ZMay 20 04:32:32.282 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
2422026-05-20T04:32:32.331ZMay 20 04:32:32.293 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
2432026-05-20T04:32:32.331ZMay 20 04:32:32.304 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
2442026-05-20T04:32:32.379ZMay 20 04:32:32.314 INFO ox: logging out
2452026-05-20T04:32:32.418ZMay 20 04:32:32.391 DEBG [sc] cr2: logging in
2462026-05-20T04:32:32.418ZMay 20 04:32:32.392 INFO ox: logged out
2472026-05-20T04:32:32.877ZMay 20 04:32:32.856 INFO cr2: mounting /opt/cargo-bay
2482026-05-20T04:32:32.877ZMay 20 04:32:32.856 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2492026-05-20T04:32:32.909ZMay 20 04:32:32.878 DEBG [sc] cr2: executing command `cd`
2502026-05-20T04:32:32.909ZMay 20 04:32:32.889 INFO cr2: finished mounting /opt/cargo-bay
2512026-05-20T04:32:32.909ZMay 20 04:32:32.889 DEBG [sc] cr2: executing command `hostname cr2`
2522026-05-20T04:32:32.944ZMay 20 04:32:32.900 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
2532026-05-20T04:32:32.944ZMay 20 04:32:32.911 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
2542026-05-20T04:32:32.944ZMay 20 04:32:32.922 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
2552026-05-20T04:32:32.983ZMay 20 04:32:32.933 INFO cr2: logging out
2562026-05-20T04:32:35.990ZMay 20 04:32:35.964 INFO cr2: logged out
2572026-05-20T04:32:36.027ZMay 20 04:32:35.964 DEBG [sc] ox: starting
2582026-05-20T04:32:36.027ZMay 20 04:32:35.964 DEBG [sc] ox: connecting to [::1]:62509
2592026-05-20T04:32:36.027ZMay 20 04:32:35.965 DEBG [sc] ox waiting for prompt
2602026-05-20T04:32:36.027ZMay 20 04:32:35.976 DEBG [sc] ox: logging in
2612026-05-20T04:32:36.087ZMay 20 04:32:36.064 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
2622026-05-20T04:32:41.886ZMay 20 04:32:41.867 DEBG [sc] ox: starting
2632026-05-20T04:32:41.886ZMay 20 04:32:41.867 DEBG [sc] ox: connecting to [::1]:62509
2642026-05-20T04:32:41.928ZMay 20 04:32:41.868 DEBG [sc] ox waiting for prompt
2652026-05-20T04:32:41.928ZMay 20 04:32:41.878 DEBG [sc] ox: logging in
2662026-05-20T04:32:41.988ZMay 20 04:32:41.966 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
2672026-05-20T04:32:42.069ZMay 20 04:32:42.044 DEBG [sc] ox: starting
2682026-05-20T04:32:42.069ZMay 20 04:32:42.044 DEBG [sc] ox: connecting to [::1]:62509
2692026-05-20T04:32:42.110ZMay 20 04:32:42.044 DEBG [sc] ox waiting for prompt
2702026-05-20T04:32:42.110ZMay 20 04:32:42.056 DEBG [sc] ox: logging in
2712026-05-20T04:32:42.161ZMay 20 04:32:42.144 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
2722026-05-20T04:32:42.227ZMay 20 04:32:42.209 INFO waiting for ceos to initialize
2732026-05-20T04:32:42.227ZMay 20 04:32:42.209 INFO cr1: installing frr
2742026-05-20T04:32:42.227ZMay 20 04:32:42.210 INFO ox: setting up npuvm
2752026-05-20T04:32:42.265ZMay 20 04:32:42.210 DEBG [sc] cr2: starting
2762026-05-20T04:32:42.265ZMay 20 04:32:42.210 DEBG [sc] cr2: connecting to [::1]:58394
2772026-05-20T04:32:42.265ZMay 20 04:32:42.210 DEBG [sc] cr1: starting
2782026-05-20T04:32:42.265ZMay 20 04:32:42.210 DEBG [sc] ox: starting
2792026-05-20T04:32:42.265ZMay 20 04:32:42.210 DEBG [sc] cr1: connecting to [::1]:62111
2802026-05-20T04:32:42.265ZMay 20 04:32:42.210 DEBG [sc] ox: connecting to [::1]:62509
2812026-05-20T04:32:42.265ZMay 20 04:32:42.210 DEBG [sc] cr2 waiting for prompt
2822026-05-20T04:32:42.265ZMay 20 04:32:42.210 DEBG [sc] cr1 waiting for prompt
2832026-05-20T04:32:42.265ZMay 20 04:32:42.210 DEBG [sc] ox waiting for prompt
2842026-05-20T04:32:42.265ZMay 20 04:32:42.220 DEBG [sc] ox: logging in
2852026-05-20T04:32:42.265ZMay 20 04:32:42.221 DEBG [sc] cr2: logging in
2862026-05-20T04:32:42.265ZMay 20 04:32:42.221 DEBG [sc] cr1: logging in
2872026-05-20T04:32:42.333ZMay 20 04:32:42.309 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
2882026-05-20T04:32:42.379ZMay 20 04:32:42.355 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
2892026-05-20T04:32:42.575ZMay 20 04:32:42.556 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
2902026-05-20T04:32:44.691ZMay 20 04:32:44.666 INFO cr2: executing eos script show version
2912026-05-20T04:32:44.735ZMay 20 04:32:44.666 DEBG [sc] cr2: starting
2922026-05-20T04:32:44.735ZMay 20 04:32:44.666 DEBG [sc] cr2: connecting to [::1]:58394
2932026-05-20T04:32:44.735ZMay 20 04:32:44.666 DEBG [sc] cr2 waiting for prompt
2942026-05-20T04:32:44.735ZMay 20 04:32:44.676 DEBG [sc] cr2: logging in
2952026-05-20T04:32:44.865ZMay 20 04:32:44.842 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
2962026-05-20T04:32:51.252ZMay 20 04:32:50.938 DEBG [sc] ox: starting
2972026-05-20T04:32:51.252ZMay 20 04:32:50.938 DEBG [sc] ox: connecting to [::1]:62509
2982026-05-20T04:32:51.635ZMay 20 04:32:50.939 DEBG [sc] ox waiting for prompt
2992026-05-20T04:32:51.635ZMay 20 04:32:50.949 DEBG [sc] ox: logging in
3002026-05-20T04:32:51.635ZMay 20 04:32:51.027 DEBG [sc] ox: executing command `chmod +x npuvm`
3012026-05-20T04:32:51.635ZMay 20 04:32:51.093 DEBG [sc] ox: starting
3022026-05-20T04:32:51.635ZMay 20 04:32:51.093 DEBG [sc] ox: connecting to [::1]:62509
3032026-05-20T04:32:51.635ZMay 20 04:32:51.093 DEBG [sc] ox waiting for prompt
3042026-05-20T04:32:51.635ZMay 20 04:32:51.103 DEBG [sc] ox: logging in
3052026-05-20T04:32:51.635ZMay 20 04:32:51.183 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
3062026-05-20T04:32:53.841ZMay 20 04:32:53.406 DEBG [sc] cr2: starting
3072026-05-20T04:32:53.841ZMay 20 04:32:53.406 DEBG [sc] cr2: connecting to [::1]:58394
3082026-05-20T04:32:54.643ZMay 20 04:32:53.407 DEBG [sc] cr2 waiting for prompt
3092026-05-20T04:32:54.643ZMay 20 04:32:53.417 DEBG [sc] cr2: logging in
3102026-05-20T04:32:54.643ZMay 20 04:32:53.561 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3112026-05-20T04:32:55.798ZMay 20 04:32:55.689 INFO cr2: executing eos script show version
3122026-05-20T04:32:55.798ZMay 20 04:32:55.689 DEBG [sc] cr2: starting
3132026-05-20T04:32:55.798ZMay 20 04:32:55.689 DEBG [sc] cr2: connecting to [::1]:58394
3142026-05-20T04:32:55.837ZMay 20 04:32:55.689 DEBG [sc] cr2 waiting for prompt
3152026-05-20T04:32:55.837ZMay 20 04:32:55.700 DEBG [sc] cr2: logging in
3162026-05-20T04:32:55.880ZMay 20 04:32:55.832 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3172026-05-20T04:32:58.233ZMay 20 04:32:58.205 DEBG [sc] cr2: starting
3182026-05-20T04:32:58.233ZMay 20 04:32:58.205 DEBG [sc] cr2: connecting to [::1]:58394
3192026-05-20T04:32:58.274ZMay 20 04:32:58.206 DEBG [sc] cr2 waiting for prompt
3202026-05-20T04:32:58.274ZMay 20 04:32:58.216 DEBG [sc] cr2: logging in
3212026-05-20T04:32:58.396ZMay 20 04:32:58.371 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3222026-05-20T04:33:00.678ZMay 20 04:33:00.519 INFO cr2: executing eos script show version
3232026-05-20T04:33:00.678ZMay 20 04:33:00.519 DEBG [sc] cr2: starting
3242026-05-20T04:33:00.678ZMay 20 04:33:00.519 DEBG [sc] cr2: connecting to [::1]:58394
3252026-05-20T04:33:00.807ZMay 20 04:33:00.520 DEBG [sc] cr2 waiting for prompt
3262026-05-20T04:33:00.807ZMay 20 04:33:00.530 DEBG [sc] cr2: logging in
3272026-05-20T04:33:00.807ZMay 20 04:33:00.674 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3282026-05-20T04:33:12.635ZMay 20 04:33:03.157 INFO cr2: executing eos script
3292026-05-20T04:33:12.635Z enable
3302026-05-20T04:33:12.635Z configure
3312026-05-20T04:33:12.635Z ipv6 unicast-routing
3322026-05-20T04:33:12.635Z ip routing ipv6 interfaces
3332026-05-20T04:33:12.635Z ip routing
3342026-05-20T04:33:12.635Z ip route 1.2.3.0/24 null0
3352026-05-20T04:33:12.635Z ipv6 route fd99::/64 null0
3362026-05-20T04:33:12.635Z interface et1
3372026-05-20T04:33:12.635Z no switchport
3382026-05-20T04:33:12.635Z ipv6 enable
3392026-05-20T04:33:12.635Z
3402026-05-20T04:33:12.635Z router bgp 45
3412026-05-20T04:33:12.635Z router-id 1.2.3.1
3422026-05-20T04:33:12.635Z no bgp default ipv4-unicast
3432026-05-20T04:33:12.635Z timers bgp 2 6
3442026-05-20T04:33:12.635Z neighbor ebgp peer group
3452026-05-20T04:33:12.635Z neighbor ebgp remote-as 33
3462026-05-20T04:33:12.635Z neighbor interface Et1 peer-group ebgp
3472026-05-20T04:33:12.635Z address-family ipv4
3482026-05-20T04:33:12.636Z neighbor ebgp activate
3492026-05-20T04:33:12.636Z neighbor ebgp next-hop address-family ipv6 originate
3502026-05-20T04:33:12.636Z network 1.2.3.0/24
3512026-05-20T04:33:12.636Z exit
3522026-05-20T04:33:12.636Z address-family ipv6
3532026-05-20T04:33:12.636Z neighbor ebgp activate
3542026-05-20T04:33:12.636Z neighbor ebgp next-hop address-family ipv6 originate
3552026-05-20T04:33:12.636Z network fd99::/64
3562026-05-20T04:33:12.636Z exit
3572026-05-20T04:33:12.636Z exit
3582026-05-20T04:33:12.636Z
3592026-05-20T04:33:12.636ZMay 20 04:33:03.157 DEBG [sc] cr2: starting
3602026-05-20T04:33:12.636ZMay 20 04:33:03.157 DEBG [sc] cr2: connecting to [::1]:58394
3612026-05-20T04:33:12.741ZMay 20 04:33:03.157 DEBG [sc] cr2 waiting for prompt
3622026-05-20T04:33:12.741ZMay 20 04:33:03.168 DEBG [sc] cr2: logging in
3632026-05-20T04:33:12.741ZMay 20 04:33:03.323 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
3642026-05-20T04:33:12.741Z enable
3652026-05-20T04:33:12.741Z configure
3662026-05-20T04:33:12.741Z ipv6 unicast-routing
3672026-05-20T04:33:12.741Z ip routing ipv6 interfaces
3682026-05-20T04:33:12.741Z ip routing
3692026-05-20T04:33:12.741Z ip route 1.2.3.0/24 null0
3702026-05-20T04:33:12.741Z ipv6 route fd99::/64 null0
3712026-05-20T04:33:12.741Z interface et1
3722026-05-20T04:33:12.741Z no switchport
3732026-05-20T04:33:12.742Z ipv6 enable
3742026-05-20T04:33:12.742Z
3752026-05-20T04:33:12.742Z router bgp 45
3762026-05-20T04:33:12.742Z router-id 1.2.3.1
3772026-05-20T04:33:12.742Z no bgp default ipv4-unicast
3782026-05-20T04:33:12.742Z timers bgp 2 6
3792026-05-20T04:33:12.742Z neighbor ebgp peer group
3802026-05-20T04:33:12.742Z neighbor ebgp remote-as 33
3812026-05-20T04:33:12.742Z neighbor interface Et1 peer-group ebgp
3822026-05-20T04:33:12.742Z address-family ipv4
3832026-05-20T04:33:12.742Z neighbor ebgp activate
3842026-05-20T04:33:12.742Z neighbor ebgp next-hop address-family ipv6 originate
3852026-05-20T04:33:12.742Z network 1.2.3.0/24
3862026-05-20T04:33:12.742Z exit
3872026-05-20T04:33:12.742Z address-family ipv6
3882026-05-20T04:33:12.742Z neighbor ebgp activate
3892026-05-20T04:33:12.742Z neighbor ebgp next-hop address-family ipv6 originate
3902026-05-20T04:33:12.742Z network fd99::/64
3912026-05-20T04:33:12.742Z exit
3922026-05-20T04:33:12.742Z exit
3932026-05-20T04:33:12.742Z '`
3942026-05-20T04:33:20.811ZMay 20 04:33:20.790 INFO cr1: enabling frr daemon bgpd
3952026-05-20T04:33:20.811ZMay 20 04:33:20.790 DEBG [sc] cr1: starting
3962026-05-20T04:33:20.811ZMay 20 04:33:20.790 DEBG [sc] cr1: connecting to [::1]:62111
3972026-05-20T04:33:20.845ZMay 20 04:33:20.791 DEBG [sc] cr1 waiting for prompt
3982026-05-20T04:33:20.845ZMay 20 04:33:20.801 DEBG [sc] cr1: logging in
3992026-05-20T04:33:20.966ZMay 20 04:33:20.944 DEBG [sc] cr1: executing command `sed -i 's/bgpd=no/bgpd=yes/g' /etc/frr/daemons`
4002026-05-20T04:33:23.042ZMay 20 04:33:23.021 DEBG [sc] cr1: starting
4012026-05-20T04:33:23.042ZMay 20 04:33:23.021 DEBG [sc] cr1: connecting to [::1]:62111
4022026-05-20T04:33:23.076ZMay 20 04:33:23.021 DEBG [sc] cr1 waiting for prompt
4032026-05-20T04:33:23.076ZMay 20 04:33:23.032 DEBG [sc] cr1: logging in
4042026-05-20T04:33:23.160ZMay 20 04:33:23.143 DEBG [sc] cr1: executing command `systemctl restart frr`
4052026-05-20T04:33:30.843ZMay 20 04:33:30.772 INFO cr1: executing frr script
4062026-05-20T04:33:30.844Z configure
4072026-05-20T04:33:30.844Z ip forwarding
4082026-05-20T04:33:30.844Z ipv6 forwarding
4092026-05-20T04:33:30.844Z ip route 1.2.3.0/24 null0
4102026-05-20T04:33:30.844Z ipv6 route fd99::/64 null0
4112026-05-20T04:33:30.844Z router bgp 44
4122026-05-20T04:33:30.844Z no bgp ebgp-requires-policy
4132026-05-20T04:33:30.844Z timers bgp 2 6
4142026-05-20T04:33:30.844Z neighbor enp0s8 interface remote-as external
4152026-05-20T04:33:30.844Z neighbor enp0s8 timers connect 1
4162026-05-20T04:33:30.844Z address-family ipv4 unicast
4172026-05-20T04:33:30.844Z network 1.2.3.0/24
4182026-05-20T04:33:30.844Z neighbor enp0s8 activate
4192026-05-20T04:33:30.844Z exit-address-family
4202026-05-20T04:33:30.844Z address-family ipv6 unicast
4212026-05-20T04:33:30.844Z network fd99::/64
4222026-05-20T04:33:30.844Z neighbor enp0s8 activate
4232026-05-20T04:33:30.844Z exit-address-family
4242026-05-20T04:33:30.844Z exit
4252026-05-20T04:33:30.844Z
4262026-05-20T04:33:30.844ZMay 20 04:33:30.772 DEBG [sc] cr1: starting
4272026-05-20T04:33:30.844ZMay 20 04:33:30.773 DEBG [sc] cr1: connecting to [::1]:62111
4282026-05-20T04:33:30.880ZMay 20 04:33:30.773 DEBG [sc] cr1 waiting for prompt
4292026-05-20T04:33:30.880ZMay 20 04:33:30.784 DEBG [sc] cr1: logging in
4302026-05-20T04:33:30.946ZMay 20 04:33:30.928 DEBG [sc] cr1: executing command `vtysh -c '' -c ' configure' -c ' ip forwarding' -c ' ipv6 forwarding' -c ' ip route 1.2.3.0/24 null0' -c ' ipv6 route fd99::/64 null0' -c ' router bgp 44' -c ' no bgp ebgp-requires-policy' -c ' timers bgp 2 6' -c ' neighbor enp0s8 interface remote-as external' -c ' neighbor enp0s8 timers connect 1 ' -c ' address-family ipv4 unicast' -c ' network 1.2.3.0/24' -c ' neighbor enp0s8 activate' -c ' exit-address-family' -c ' address-family ipv6 unicast' -c ' network fd99::/64' -c ' neighbor enp0s8 activate' -c ' exit-address-family' -c ' exit' -c ' '`
4312026-05-20T04:35:39.365ZMay 20 04:35:39.348 DEBG [sc] ox: starting
4322026-05-20T04:35:39.365ZMay 20 04:35:39.348 DEBG [sc] ox: connecting to [::1]:62509
4332026-05-20T04:35:39.398ZMay 20 04:35:39.349 DEBG [sc] ox waiting for prompt
4342026-05-20T04:35:39.398ZMay 20 04:35:39.358 DEBG [sc] ox: logging in
4352026-05-20T04:35:39.451ZMay 20 04:35:39.435 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
4362026-05-20T04:35:39.714ZMay 20 04:35:39.697 DEBG [sc] ox: starting
4372026-05-20T04:35:39.714ZMay 20 04:35:39.697 DEBG [sc] ox: connecting to [::1]:62509
4382026-05-20T04:35:39.758ZMay 20 04:35:39.698 DEBG [sc] ox waiting for prompt
4392026-05-20T04:35:39.758ZMay 20 04:35:39.709 DEBG [sc] ox: logging in
4402026-05-20T04:35:39.801ZMay 20 04:35:39.786 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4412026-05-20T04:35:40.828ZMay 20 04:35:40.810 DEBG [sc] ox: starting
4422026-05-20T04:35:40.828ZMay 20 04:35:40.810 DEBG [sc] ox: connecting to [::1]:62509
4432026-05-20T04:35:40.863ZMay 20 04:35:40.810 DEBG [sc] ox waiting for prompt
4442026-05-20T04:35:40.863ZMay 20 04:35:40.810 DEBG [sc] ox: logging in
4452026-05-20T04:35:40.947ZMay 20 04:35:40.887 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4462026-05-20T04:35:40.992ZMay 20 04:35:40.943 DEBG [sc] ox: starting
4472026-05-20T04:35:40.992ZMay 20 04:35:40.943 DEBG [sc] ox: connecting to [::1]:62509
4482026-05-20T04:35:40.992ZMay 20 04:35:40.943 DEBG [sc] ox waiting for prompt
4492026-05-20T04:35:40.992ZMay 20 04:35:40.954 DEBG [sc] ox: logging in
4502026-05-20T04:35:41.049ZMay 20 04:35:41.031 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
4512026-05-20T04:35:41.103ZMay 20 04:35:41.087 DEBG [sc] ox: starting
4522026-05-20T04:35:41.103ZMay 20 04:35:41.087 DEBG [sc] ox: connecting to [::1]:62509
4532026-05-20T04:35:41.135ZMay 20 04:35:41.088 DEBG [sc] ox waiting for prompt
4542026-05-20T04:35:41.135ZMay 20 04:35:41.098 DEBG [sc] ox: logging in
4552026-05-20T04:35:41.194ZMay 20 04:35:41.175 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
4562026-05-20T04:35:41.253ZMay 20 04:35:41.231 DEBG [sc] ox: starting
4572026-05-20T04:35:41.253ZMay 20 04:35:41.231 DEBG [sc] ox: connecting to [::1]:62509
4582026-05-20T04:35:41.297ZMay 20 04:35:41.232 DEBG [sc] ox waiting for prompt
4592026-05-20T04:35:41.297ZMay 20 04:35:41.241 DEBG [sc] ox: logging in
4602026-05-20T04:35:41.335ZMay 20 04:35:41.319 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
4612026-05-20T04:35:41.398ZMay 20 04:35:41.375 DEBG [sc] ox: starting
4622026-05-20T04:35:41.398ZMay 20 04:35:41.375 DEBG [sc] ox: connecting to [::1]:62509
4632026-05-20T04:35:41.429ZMay 20 04:35:41.376 DEBG [sc] ox waiting for prompt
4642026-05-20T04:35:41.429ZMay 20 04:35:41.386 DEBG [sc] ox: logging in
4652026-05-20T04:35:41.488ZMay 20 04:35:41.463 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
4662026-05-20T04:35:41.547ZMay 20 04:35:41.530 DEBG [sc] ox: starting
4672026-05-20T04:35:41.547ZMay 20 04:35:41.530 DEBG [sc] ox: connecting to [::1]:62509
4682026-05-20T04:35:41.581ZMay 20 04:35:41.531 DEBG [sc] ox waiting for prompt
4692026-05-20T04:35:41.581ZMay 20 04:35:41.540 DEBG [sc] ox: logging in
4702026-05-20T04:35:41.633ZMay 20 04:35:41.617 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
4712026-05-20T04:35:41.696ZMay 20 04:35:41.673 DEBG [sc] ox: starting
4722026-05-20T04:35:41.696ZMay 20 04:35:41.673 DEBG [sc] ox: connecting to [::1]:62509
4732026-05-20T04:35:41.728ZMay 20 04:35:41.674 DEBG [sc] ox waiting for prompt
4742026-05-20T04:35:41.728ZMay 20 04:35:41.683 DEBG [sc] ox: logging in
4752026-05-20T04:35:41.778ZMay 20 04:35:41.761 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
4762026-05-20T04:35:41.844ZMay 20 04:35:41.815 DEBG [sc] ox: starting
4772026-05-20T04:35:41.845ZMay 20 04:35:41.815 DEBG [sc] ox: connecting to [::1]:62509
4782026-05-20T04:35:41.878ZMay 20 04:35:41.816 DEBG [sc] ox waiting for prompt
4792026-05-20T04:35:41.878ZMay 20 04:35:41.826 DEBG [sc] ox: logging in
4802026-05-20T04:35:41.925ZMay 20 04:35:41.904 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
4812026-05-20T04:35:41.993ZMay 20 04:35:41.974 INFO adding BGP router to mgd
4822026-05-20T04:35:44.500ZMay 20 04:35:44.481 INFO cr1: executing frr script show ip bgp json
4832026-05-20T04:35:44.500ZMay 20 04:35:44.481 DEBG [sc] cr1: starting
4842026-05-20T04:35:44.500ZMay 20 04:35:44.481 DEBG [sc] cr1: connecting to [::1]:62111
4852026-05-20T04:35:44.538ZMay 20 04:35:44.481 DEBG [sc] cr1 waiting for prompt
4862026-05-20T04:35:44.538ZMay 20 04:35:44.493 DEBG [sc] cr1: logging in
4872026-05-20T04:35:44.824ZMay 20 04:35:44.808 DEBG [sc] cr1: executing command `vtysh -c 'show ip bgp json'`
4882026-05-20T04:35:46.960ZMay 20 04:35:46.935 INFO cr1: executing frr script show bgp json
4892026-05-20T04:35:46.960ZMay 20 04:35:46.935 DEBG [sc] cr1: starting
4902026-05-20T04:35:46.960ZMay 20 04:35:46.935 DEBG [sc] cr1: connecting to [::1]:62111
4912026-05-20T04:35:47.035ZMay 20 04:35:46.936 DEBG [sc] cr1 waiting for prompt
4922026-05-20T04:35:47.035ZMay 20 04:35:46.946 DEBG [sc] cr1: logging in
4932026-05-20T04:35:47.157ZMay 20 04:35:47.100 DEBG [sc] cr1: executing command `vtysh -c 'show bgp json'`
4942026-05-20T04:35:49.355ZMay 20 04:35:49.227 INFO cr2: executing eos script show ip bgp | json
4952026-05-20T04:35:49.355ZMay 20 04:35:49.227 DEBG [sc] cr2: starting
4962026-05-20T04:35:49.355ZMay 20 04:35:49.227 DEBG [sc] cr2: connecting to [::1]:58394
4972026-05-20T04:35:49.355ZMay 20 04:35:49.227 DEBG [sc] cr2 waiting for prompt
4982026-05-20T04:35:49.355ZMay 20 04:35:49.239 DEBG [sc] cr2: logging in
4992026-05-20T04:35:49.627ZMay 20 04:35:49.602 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ip bgp | json'`
5002026-05-20T04:35:51.991ZMay 20 04:35:51.969 INFO cr2: executing eos script show ipv6 bgp | json
5012026-05-20T04:35:51.991ZMay 20 04:35:51.969 DEBG [sc] cr2: starting
5022026-05-20T04:35:51.991ZMay 20 04:35:51.969 DEBG [sc] cr2: connecting to [::1]:58394
5032026-05-20T04:35:52.026ZMay 20 04:35:51.970 DEBG [sc] cr2 waiting for prompt
5042026-05-20T04:35:52.026ZMay 20 04:35:51.980 DEBG [sc] cr2: logging in
5052026-05-20T04:35:52.144ZMay 20 04:35:52.123 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ipv6 bgp | json'`
5062026-05-20T04:35:54.509ZMay 20 04:35:54.485 INFO trio bgp unnumbered test passed 🎉
5072026-05-20T04:35:54.542ZMay 20 04:35:54.485 INFO destroying runner for deployment mgtriou
5082026-05-20T04:35:54.542ZMay 20 04:35:54.485 INFO destroying deployment mgtriou
5092026-05-20T04:35:54.542ZMay 20 04:35:54.485 INFO destroying nodes
5102026-05-20T04:35:54.628ZMay 20 04:35:54.600 INFO destroying links
5112026-05-20T04:35:54.628ZMay 20 04:35:54.600 INFO destroying link mgtriou_ox_sn_vnic0
5122026-05-20T04:35:54.675ZMay 20 04:35:54.603 INFO destroying link mgtriou_ox_sn_sim0
5132026-05-20T04:35:54.675ZMay 20 04:35:54.604 INFO destroying link mgtriou_cr1_vn_vnic0
5142026-05-20T04:35:55.629ZMay 20 04:35:55.607 INFO destroying link mgtriou_cr1_vn_sim0
5152026-05-20T04:35:55.663ZMay 20 04:35:55.608 INFO destroying link mgtriou_ox_sn_vnic1
5162026-05-20T04:35:55.664ZMay 20 04:35:55.610 INFO destroying link mgtriou_ox_sn_sim1
5172026-05-20T04:35:55.664ZMay 20 04:35:55.611 INFO destroying link mgtriou_cr2_vn_vnic0
5182026-05-20T04:35:55.664ZMay 20 04:35:55.612 INFO destroying link mgtriou_cr2_vn_sim0
5192026-05-20T04:35:55.664ZMay 20 04:35:55.613 INFO destroying external links
5202026-05-20T04:35:55.664ZMay 20 04:35:55.613 INFO destroying external link mgtriou_ox_vn_vnic2
5212026-05-20T04:35:55.664ZMay 20 04:35:55.614 INFO destroying external link mgtriou_cr1_vn_vnic1
5222026-05-20T04:35:55.664ZMay 20 04:35:55.616 INFO destroying external link mgtriou_cr2_vn_vnic1
5232026-05-20T04:35:55.664ZMay 20 04:35:55.617 INFO destroying images
5242026-05-20T04:35:56.127ZMay 20 04:35:56.103 INFO destroying workspace at .falcon
5252026-05-20T04:35:56.168Z+ RUST_LOG=debug
5262026-05-20T04:35:56.168Z+ pfexec ./falcon-lab run trio-bfd-static-routing
5272026-05-20T04:35:56.206ZMay 20 04:35:56.146 DEBG using default route interface igb0
5282026-05-20T04:35:56.206ZMay 20 04:35:56.147 DEBG using default route interface igb0
5292026-05-20T04:35:56.206ZMay 20 04:35:56.147 DEBG using default route interface igb0
5302026-05-20T04:35:56.206ZMay 20 04:35:56.147 INFO launching runner: deployment(mgtriobfd) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
5312026-05-20T04:35:56.206ZMay 20 04:35:56.147 INFO starting preflight for deployment mgtriobfd
5322026-05-20T04:35:56.963ZMay 20 04:35:56.947 INFO creating links
5332026-05-20T04:35:56.963ZMay 20 04:35:56.947 DEBG destroying link mgtriobfd_ox_sn_vnic0
5342026-05-20T04:35:56.963ZMay 20 04:35:56.947 DEBG destroying link mgtriobfd_ox_sn_sim0
5352026-05-20T04:35:56.998ZMay 20 04:35:56.947 INFO creating simnet link 'mgtriobfd_ox_sn_sim0'
5362026-05-20T04:35:56.998ZMay 20 04:35:56.949 INFO creating vnic link 'mgtriobfd_ox_sn_vnic0'
5372026-05-20T04:35:56.998ZMay 20 04:35:56.956 DEBG link pair created
5382026-05-20T04:35:56.998ZMay 20 04:35:56.956 DEBG destroying link mgtriobfd_cr1_vn_vnic0
5392026-05-20T04:35:56.998ZMay 20 04:35:56.956 DEBG destroying link mgtriobfd_cr1_vn_sim0
5402026-05-20T04:35:56.998ZMay 20 04:35:56.956 INFO creating simnet link 'mgtriobfd_cr1_vn_sim0'
5412026-05-20T04:35:56.998ZMay 20 04:35:56.957 INFO creating vnic link 'mgtriobfd_cr1_vn_vnic0'
5422026-05-20T04:35:56.998ZMay 20 04:35:56.964 DEBG link pair created
5432026-05-20T04:35:56.998ZMay 20 04:35:56.964 DEBG destroying link mgtriobfd_ox_sn_vnic1
5442026-05-20T04:35:56.998ZMay 20 04:35:56.964 DEBG destroying link mgtriobfd_ox_sn_sim1
5452026-05-20T04:35:56.998ZMay 20 04:35:56.964 INFO creating simnet link 'mgtriobfd_ox_sn_sim1'
5462026-05-20T04:35:56.998ZMay 20 04:35:56.965 INFO creating vnic link 'mgtriobfd_ox_sn_vnic1'
5472026-05-20T04:35:56.998ZMay 20 04:35:56.971 DEBG link pair created
5482026-05-20T04:35:56.998ZMay 20 04:35:56.971 DEBG destroying link mgtriobfd_cr2_vn_vnic0
5492026-05-20T04:35:56.998ZMay 20 04:35:56.971 DEBG destroying link mgtriobfd_cr2_vn_sim0
5502026-05-20T04:35:56.998ZMay 20 04:35:56.971 INFO creating simnet link 'mgtriobfd_cr2_vn_sim0'
5512026-05-20T04:35:56.998ZMay 20 04:35:56.973 INFO creating vnic link 'mgtriobfd_cr2_vn_vnic0'
5522026-05-20T04:35:57.033ZMay 20 04:35:56.979 DEBG link pair created
5532026-05-20T04:35:57.033ZMay 20 04:35:56.980 INFO creating external links
5542026-05-20T04:35:57.033ZMay 20 04:35:56.980 DEBG destroying external link mgtriobfd_ox_vn_vnic2
5552026-05-20T04:35:57.033ZMay 20 04:35:56.980 INFO creating external link mgtriobfd_ox_vn_vnic2
5562026-05-20T04:35:57.033ZMay 20 04:35:56.981 DEBG external link mgtriobfd_ox_vn_vnic2@igb0 created
5572026-05-20T04:35:57.033ZMay 20 04:35:56.981 DEBG destroying external link mgtriobfd_cr1_vn_vnic1
5582026-05-20T04:35:57.033ZMay 20 04:35:56.981 INFO creating external link mgtriobfd_cr1_vn_vnic1
5592026-05-20T04:35:57.033ZMay 20 04:35:56.982 DEBG external link mgtriobfd_cr1_vn_vnic1@igb0 created
5602026-05-20T04:35:57.033ZMay 20 04:35:56.982 DEBG destroying external link mgtriobfd_cr2_vn_vnic1
5612026-05-20T04:35:57.033ZMay 20 04:35:56.982 INFO creating external link mgtriobfd_cr2_vn_vnic1
5622026-05-20T04:35:57.033ZMay 20 04:35:56.983 DEBG external link mgtriobfd_cr2_vn_vnic1@igb0 created
5632026-05-20T04:35:57.033ZMay 20 04:35:56.983 INFO creating nodes
5642026-05-20T04:35:57.033ZMay 20 04:35:56.983 INFO ox: launching node
5652026-05-20T04:35:57.033ZMay 20 04:35:56.986 INFO cr1: launching node
5662026-05-20T04:35:57.033ZMay 20 04:35:56.988 INFO cr2: launching node
5672026-05-20T04:35:57.033ZMay 20 04:35:57.002 INFO launched instance ox with pid 878 on port 61527
5682026-05-20T04:35:57.033ZMay 20 04:35:57.002 INFO ox: instance ensure
5692026-05-20T04:35:57.033ZMay 20 04:35:57.002 INFO launched instance cr1 with pid 879 on port 36148
5702026-05-20T04:35:57.033ZMay 20 04:35:57.002 INFO cr1: instance ensure
5712026-05-20T04:35:57.033ZMay 20 04:35:57.003 INFO launched instance cr2 with pid 880 on port 40160
5722026-05-20T04:35:57.033ZMay 20 04:35:57.003 INFO cr2: instance ensure
5732026-05-20T04:35:59.256ZMay 20 04:35:59.237 INFO cr1: instance ensure completed after 0 retries
5742026-05-20T04:35:59.257ZMay 20 04:35:59.237 INFO cr1: instance run
5752026-05-20T04:35:59.292ZMay 20 04:35:59.238 DEBG [sc] cr1: starting
5762026-05-20T04:35:59.292ZMay 20 04:35:59.238 DEBG [sc] cr1: connecting to [::1]:36148
5772026-05-20T04:35:59.292ZMay 20 04:35:59.238 DEBG [sc] cr1 waiting for prompt
5782026-05-20T04:35:59.292ZMay 20 04:35:59.265 INFO ox: instance ensure completed after 0 retries
5792026-05-20T04:35:59.292ZMay 20 04:35:59.265 INFO ox: instance run
5802026-05-20T04:35:59.292ZMay 20 04:35:59.265 DEBG [sc] ox: starting
5812026-05-20T04:35:59.292ZMay 20 04:35:59.265 DEBG [sc] ox: connecting to [::1]:61527
5822026-05-20T04:35:59.292ZMay 20 04:35:59.266 DEBG [sc] ox waiting for prompt
5832026-05-20T04:35:59.292ZMay 20 04:35:59.272 INFO cr2: instance ensure completed after 0 retries
5842026-05-20T04:35:59.293ZMay 20 04:35:59.272 INFO cr2: instance run
5852026-05-20T04:35:59.336ZMay 20 04:35:59.272 DEBG [sc] cr2: starting
5862026-05-20T04:35:59.336ZMay 20 04:35:59.272 DEBG [sc] cr2: connecting to [::1]:40160
5872026-05-20T04:35:59.336ZMay 20 04:35:59.273 DEBG [sc] cr2 waiting for prompt
5882026-05-20T04:36:16.384ZMay 20 04:36:16.366 DEBG [sc] cr1: logging in
5892026-05-20T04:36:16.765ZMay 20 04:36:16.747 INFO cr1: mounting /opt/cargo-bay
5902026-05-20T04:36:16.765ZMay 20 04:36:16.747 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5912026-05-20T04:36:16.803ZMay 20 04:36:16.759 DEBG [sc] cr1: executing command `cd`
5922026-05-20T04:36:16.803ZMay 20 04:36:16.770 INFO cr1: finished mounting /opt/cargo-bay
5932026-05-20T04:36:16.803ZMay 20 04:36:16.770 DEBG [sc] cr1: executing command `hostname cr1`
5942026-05-20T04:36:16.804ZMay 20 04:36:16.780 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
5952026-05-20T04:36:16.844ZMay 20 04:36:16.791 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
5962026-05-20T04:36:16.844ZMay 20 04:36:16.803 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
5972026-05-20T04:36:16.844ZMay 20 04:36:16.813 INFO cr1: logging out
5982026-05-20T04:36:18.896ZMay 20 04:36:18.878 INFO cr1: logged out
5992026-05-20T04:36:20.101ZMay 20 04:36:20.059 DEBG [sc] ox: logging in
6002026-05-20T04:36:20.266ZMay 20 04:36:20.247 INFO ox: mounting /opt/cargo-bay
6012026-05-20T04:36:20.267ZMay 20 04:36:20.247 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
6022026-05-20T04:36:21.013ZMay 20 04:36:20.995 DEBG [sc] cr2: logging in
6032026-05-20T04:36:21.386ZMay 20 04:36:21.368 INFO cr2: mounting /opt/cargo-bay
6042026-05-20T04:36:21.386ZMay 20 04:36:21.368 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
6052026-05-20T04:36:21.433ZMay 20 04:36:21.389 DEBG [sc] cr2: executing command `cd`
6062026-05-20T04:36:21.433ZMay 20 04:36:21.400 INFO cr2: finished mounting /opt/cargo-bay
6072026-05-20T04:36:21.433ZMay 20 04:36:21.401 DEBG [sc] cr2: executing command `hostname cr2`
6082026-05-20T04:36:21.467ZMay 20 04:36:21.412 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
6092026-05-20T04:36:21.467ZMay 20 04:36:21.423 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
6102026-05-20T04:36:21.468ZMay 20 04:36:21.434 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
6112026-05-20T04:36:21.468ZMay 20 04:36:21.444 INFO cr2: logging out
6122026-05-20T04:36:21.612ZMay 20 04:36:21.596 DEBG [sc] ox: executing command `cd`
6132026-05-20T04:36:21.644ZMay 20 04:36:21.607 INFO ox: finished mounting /opt/cargo-bay
6142026-05-20T04:36:21.644ZMay 20 04:36:21.607 DEBG [sc] ox: executing command `hostname ox`
6152026-05-20T04:36:21.644ZMay 20 04:36:21.618 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
6162026-05-20T04:36:21.681ZMay 20 04:36:21.629 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
6172026-05-20T04:36:21.681ZMay 20 04:36:21.640 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
6182026-05-20T04:36:21.681ZMay 20 04:36:21.651 INFO ox: logging out
6192026-05-20T04:36:21.784ZMay 20 04:36:21.767 INFO ox: logged out
6202026-05-20T04:36:24.467ZMay 20 04:36:24.449 INFO cr2: logged out
6212026-05-20T04:36:24.499ZMay 20 04:36:24.449 DEBG [sc] ox: starting
6222026-05-20T04:36:24.499ZMay 20 04:36:24.449 DEBG [sc] ox: connecting to [::1]:61527
6232026-05-20T04:36:24.500ZMay 20 04:36:24.450 DEBG [sc] ox waiting for prompt
6242026-05-20T04:36:24.500ZMay 20 04:36:24.461 DEBG [sc] ox: logging in
6252026-05-20T04:36:24.569ZMay 20 04:36:24.550 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
6262026-05-20T04:36:30.292ZMay 20 04:36:30.271 DEBG [sc] ox: starting
6272026-05-20T04:36:30.293ZMay 20 04:36:30.271 DEBG [sc] ox: connecting to [::1]:61527
6282026-05-20T04:36:30.330ZMay 20 04:36:30.272 DEBG [sc] ox waiting for prompt
6292026-05-20T04:36:30.330ZMay 20 04:36:30.282 DEBG [sc] ox: logging in
6302026-05-20T04:36:30.393ZMay 20 04:36:30.370 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
6312026-05-20T04:36:30.477ZMay 20 04:36:30.458 DEBG [sc] ox: starting
6322026-05-20T04:36:30.477ZMay 20 04:36:30.458 DEBG [sc] ox: connecting to [::1]:61527
6332026-05-20T04:36:30.510ZMay 20 04:36:30.458 DEBG [sc] ox waiting for prompt
6342026-05-20T04:36:30.510ZMay 20 04:36:30.469 DEBG [sc] ox: logging in
6352026-05-20T04:36:30.573ZMay 20 04:36:30.556 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
6362026-05-20T04:36:30.640ZMay 20 04:36:30.623 INFO waiting for ceos to initialize
6372026-05-20T04:36:30.640ZMay 20 04:36:30.623 INFO cr1: installing frr
6382026-05-20T04:36:30.640ZMay 20 04:36:30.623 INFO ox: setting up npuvm
6392026-05-20T04:36:30.676ZMay 20 04:36:30.623 DEBG [sc] cr2: starting
6402026-05-20T04:36:30.677ZMay 20 04:36:30.623 DEBG [sc] cr2: connecting to [::1]:40160
6412026-05-20T04:36:30.677ZMay 20 04:36:30.623 DEBG [sc] cr1: starting
6422026-05-20T04:36:30.677ZMay 20 04:36:30.623 DEBG [sc] cr1: connecting to [::1]:36148
6432026-05-20T04:36:30.677ZMay 20 04:36:30.623 DEBG [sc] ox: starting
6442026-05-20T04:36:30.677ZMay 20 04:36:30.623 DEBG [sc] ox: connecting to [::1]:61527
6452026-05-20T04:36:30.677ZMay 20 04:36:30.623 DEBG [sc] cr2 waiting for prompt
6462026-05-20T04:36:30.677ZMay 20 04:36:30.624 DEBG [sc] cr1 waiting for prompt
6472026-05-20T04:36:30.677ZMay 20 04:36:30.624 DEBG [sc] ox waiting for prompt
6482026-05-20T04:36:30.677ZMay 20 04:36:30.634 DEBG [sc] cr1: logging in
6492026-05-20T04:36:30.677ZMay 20 04:36:30.634 DEBG [sc] ox: logging in
6502026-05-20T04:36:30.677ZMay 20 04:36:30.635 DEBG [sc] cr2: logging in
6512026-05-20T04:36:30.730ZMay 20 04:36:30.711 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
6522026-05-20T04:36:30.816ZMay 20 04:36:30.799 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6532026-05-20T04:36:31.091ZMay 20 04:36:31.072 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
6542026-05-20T04:36:33.068ZMay 20 04:36:33.044 INFO cr2: executing eos script show version
6552026-05-20T04:36:33.068ZMay 20 04:36:33.044 DEBG [sc] cr2: starting
6562026-05-20T04:36:33.068ZMay 20 04:36:33.044 DEBG [sc] cr2: connecting to [::1]:40160
6572026-05-20T04:36:33.102ZMay 20 04:36:33.045 DEBG [sc] cr2 waiting for prompt
6582026-05-20T04:36:33.102ZMay 20 04:36:33.055 DEBG [sc] cr2: logging in
6592026-05-20T04:36:33.221ZMay 20 04:36:33.199 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6602026-05-20T04:36:41.283ZMay 20 04:36:41.259 DEBG [sc] cr2: starting
6612026-05-20T04:36:41.283ZMay 20 04:36:41.259 DEBG [sc] cr2: connecting to [::1]:40160
6622026-05-20T04:36:41.326ZMay 20 04:36:41.260 DEBG [sc] cr2 waiting for prompt
6632026-05-20T04:36:41.326ZMay 20 04:36:41.271 DEBG [sc] cr2: logging in
6642026-05-20T04:36:41.412ZMay 20 04:36:41.392 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6652026-05-20T04:36:43.508ZMay 20 04:36:43.484 INFO cr2: executing eos script show version
6662026-05-20T04:36:43.508ZMay 20 04:36:43.484 DEBG [sc] cr2: starting
6672026-05-20T04:36:43.508ZMay 20 04:36:43.484 DEBG [sc] cr2: connecting to [::1]:40160
6682026-05-20T04:36:43.547ZMay 20 04:36:43.485 DEBG [sc] cr2 waiting for prompt
6692026-05-20T04:36:43.548ZMay 20 04:36:43.495 DEBG [sc] cr2: logging in
6702026-05-20T04:36:43.671ZMay 20 04:36:43.648 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6712026-05-20T04:36:45.108ZMay 20 04:36:45.079 DEBG [sc] ox: starting
6722026-05-20T04:36:45.108ZMay 20 04:36:45.079 DEBG [sc] ox: connecting to [::1]:61527
6732026-05-20T04:36:45.140ZMay 20 04:36:45.080 DEBG [sc] ox waiting for prompt
6742026-05-20T04:36:45.140ZMay 20 04:36:45.091 DEBG [sc] ox: logging in
6752026-05-20T04:36:45.186ZMay 20 04:36:45.168 DEBG [sc] ox: executing command `chmod +x npuvm`
6762026-05-20T04:36:45.260ZMay 20 04:36:45.234 DEBG [sc] ox: starting
6772026-05-20T04:36:45.260ZMay 20 04:36:45.234 DEBG [sc] ox: connecting to [::1]:61527
6782026-05-20T04:36:45.291ZMay 20 04:36:45.235 DEBG [sc] ox waiting for prompt
6792026-05-20T04:36:45.291ZMay 20 04:36:45.245 DEBG [sc] ox: logging in
6802026-05-20T04:36:45.341ZMay 20 04:36:45.322 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
6812026-05-20T04:36:46.071ZMay 20 04:36:46.047 DEBG [sc] cr2: starting
6822026-05-20T04:36:46.071ZMay 20 04:36:46.047 DEBG [sc] cr2: connecting to [::1]:40160
6832026-05-20T04:36:46.107ZMay 20 04:36:46.047 DEBG [sc] cr2 waiting for prompt
6842026-05-20T04:36:46.107ZMay 20 04:36:46.057 DEBG [sc] cr2: logging in
6852026-05-20T04:36:46.212ZMay 20 04:36:46.190 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6862026-05-20T04:36:48.336ZMay 20 04:36:48.317 INFO cr2: executing eos script show version
6872026-05-20T04:36:48.336ZMay 20 04:36:48.317 DEBG [sc] cr2: starting
6882026-05-20T04:36:48.336ZMay 20 04:36:48.317 DEBG [sc] cr2: connecting to [::1]:40160
6892026-05-20T04:36:48.372ZMay 20 04:36:48.317 DEBG [sc] cr2 waiting for prompt
6902026-05-20T04:36:48.372ZMay 20 04:36:48.328 DEBG [sc] cr2: logging in
6912026-05-20T04:36:48.495ZMay 20 04:36:48.475 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6922026-05-20T04:36:51.004ZMay 20 04:36:50.979 INFO cr2: executing eos script
6932026-05-20T04:36:51.005Z enable
6942026-05-20T04:36:51.005Z configure
6952026-05-20T04:36:51.005Z ip routing
6962026-05-20T04:36:51.005Z ipv6 unicast-routing
6972026-05-20T04:36:51.005Z interface Ethernet1
6982026-05-20T04:36:51.005Z no switchport
6992026-05-20T04:36:51.005Z ip address 10.0.1.2/24
7002026-05-20T04:36:51.005Z ipv6 enable
7012026-05-20T04:36:51.005Z ipv6 address fd00:2::2/64
7022026-05-20T04:36:51.005Z bfd interval 300 min-rx 300 multiplier 3
7032026-05-20T04:36:51.005Z exit
7042026-05-20T04:36:51.005Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7052026-05-20T04:36:51.005Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7062026-05-20T04:36:51.005Z exit
7072026-05-20T04:36:51.005Z
7082026-05-20T04:36:51.005ZMay 20 04:36:50.979 DEBG [sc] cr2: starting
7092026-05-20T04:36:51.005ZMay 20 04:36:50.979 DEBG [sc] cr2: connecting to [::1]:40160
7102026-05-20T04:36:51.041ZMay 20 04:36:50.979 DEBG [sc] cr2 waiting for prompt
7112026-05-20T04:36:51.041ZMay 20 04:36:50.991 DEBG [sc] cr2: logging in
7122026-05-20T04:36:51.132ZMay 20 04:36:51.113 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
7132026-05-20T04:36:51.132Z enable
7142026-05-20T04:36:51.132Z configure
7152026-05-20T04:36:51.132Z ip routing
7162026-05-20T04:36:51.132Z ipv6 unicast-routing
7172026-05-20T04:36:51.132Z interface Ethernet1
7182026-05-20T04:36:51.132Z no switchport
7192026-05-20T04:36:51.132Z ip address 10.0.1.2/24
7202026-05-20T04:36:51.132Z ipv6 enable
7212026-05-20T04:36:51.132Z ipv6 address fd00:2::2/64
7222026-05-20T04:36:51.132Z bfd interval 300 min-rx 300 multiplier 3
7232026-05-20T04:36:51.132Z exit
7242026-05-20T04:36:51.132Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7252026-05-20T04:36:51.132Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7262026-05-20T04:36:51.132Z exit
7272026-05-20T04:36:51.132Z '`
7282026-05-20T04:37:09.371ZMay 20 04:37:09.352 INFO cr1: enabling frr daemon bfdd
7292026-05-20T04:37:09.371ZMay 20 04:37:09.352 DEBG [sc] cr1: starting
7302026-05-20T04:37:09.371ZMay 20 04:37:09.352 DEBG [sc] cr1: connecting to [::1]:36148
7312026-05-20T04:37:09.415ZMay 20 04:37:09.353 DEBG [sc] cr1 waiting for prompt
7322026-05-20T04:37:09.415ZMay 20 04:37:09.364 DEBG [sc] cr1: logging in
7332026-05-20T04:37:09.539ZMay 20 04:37:09.518 DEBG [sc] cr1: executing command `sed -i 's/bfdd=no/bfdd=yes/g' /etc/frr/daemons`
7342026-05-20T04:37:11.608ZMay 20 04:37:11.587 DEBG [sc] cr1: starting
7352026-05-20T04:37:11.608ZMay 20 04:37:11.587 DEBG [sc] cr1: connecting to [::1]:36148
7362026-05-20T04:37:11.648ZMay 20 04:37:11.587 DEBG [sc] cr1 waiting for prompt
7372026-05-20T04:37:11.648ZMay 20 04:37:11.597 DEBG [sc] cr1: logging in
7382026-05-20T04:37:11.762ZMay 20 04:37:11.741 DEBG [sc] cr1: executing command `systemctl restart frr`
7392026-05-20T04:37:19.353ZMay 20 04:37:19.329 INFO cr1: executing frr script
7402026-05-20T04:37:19.353Z configure
7412026-05-20T04:37:19.353Z interface enp0s8
7422026-05-20T04:37:19.353Z ip address 10.0.0.2/24
7432026-05-20T04:37:19.353Z ipv6 address fd00:1::2/64
7442026-05-20T04:37:19.353Z no shutdown
7452026-05-20T04:37:19.353Z exit
7462026-05-20T04:37:19.353Z bfd
7472026-05-20T04:37:19.353Z peer 10.0.0.1 local-address 10.0.0.2
7482026-05-20T04:37:19.354Z detect-multiplier 3
7492026-05-20T04:37:19.354Z receive-interval 300
7502026-05-20T04:37:19.354Z transmit-interval 300
7512026-05-20T04:37:19.354Z no shutdown
7522026-05-20T04:37:19.354Z exit
7532026-05-20T04:37:19.354Z peer fd00:1::1 local-address fd00:1::2
7542026-05-20T04:37:19.354Z detect-multiplier 3
7552026-05-20T04:37:19.354Z receive-interval 300
7562026-05-20T04:37:19.354Z transmit-interval 300
7572026-05-20T04:37:19.354Z no shutdown
7582026-05-20T04:37:19.354Z exit
7592026-05-20T04:37:19.354Z exit
7602026-05-20T04:37:19.354Z
7612026-05-20T04:37:19.354ZMay 20 04:37:19.329 DEBG [sc] cr1: starting
7622026-05-20T04:37:19.391ZMay 20 04:37:19.329 DEBG [sc] cr1: connecting to [::1]:36148
7632026-05-20T04:37:19.391ZMay 20 04:37:19.330 DEBG [sc] cr1 waiting for prompt
7642026-05-20T04:37:19.391ZMay 20 04:37:19.341 DEBG [sc] cr1: logging in
7652026-05-20T04:37:19.499ZMay 20 04:37:19.473 DEBG [sc] cr1: executing command `vtysh -c '' -c ' configure' -c ' interface enp0s8' -c ' ip address 10.0.0.2/24' -c ' ipv6 address fd00:1::2/64' -c ' no shutdown' -c ' exit' -c ' bfd' -c ' peer 10.0.0.1 local-address 10.0.0.2' -c ' detect-multiplier 3' -c ' receive-interval 300' -c ' transmit-interval 300' -c ' no shutdown' -c ' exit' -c ' peer fd00:1::1 local-address fd00:1::2' -c ' detect-multiplier 3' -c ' receive-interval 300' -c ' transmit-interval 300' -c ' no shutdown' -c ' exit' -c ' exit' -c ' '`
7662026-05-20T04:38:56.596ZMay 20 04:38:56.579 DEBG [sc] ox: starting
7672026-05-20T04:38:56.596ZMay 20 04:38:56.579 DEBG [sc] ox: connecting to [::1]:61527
7682026-05-20T04:38:56.627ZMay 20 04:38:56.580 DEBG [sc] ox waiting for prompt
7692026-05-20T04:38:56.627ZMay 20 04:38:56.590 DEBG [sc] ox: logging in
7702026-05-20T04:38:56.685ZMay 20 04:38:56.667 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
7712026-05-20T04:38:57.183ZMay 20 04:38:57.164 DEBG [sc] ox: starting
7722026-05-20T04:38:57.183ZMay 20 04:38:57.164 DEBG [sc] ox: connecting to [::1]:61527
7732026-05-20T04:38:57.222ZMay 20 04:38:57.165 DEBG [sc] ox waiting for prompt
7742026-05-20T04:38:57.222ZMay 20 04:38:57.176 DEBG [sc] ox: logging in
7752026-05-20T04:38:57.277ZMay 20 04:38:57.254 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7762026-05-20T04:38:57.351ZMay 20 04:38:57.321 DEBG [sc] ox: starting
7772026-05-20T04:38:57.351ZMay 20 04:38:57.321 DEBG [sc] ox: connecting to [::1]:61527
7782026-05-20T04:38:57.394ZMay 20 04:38:57.322 DEBG [sc] ox waiting for prompt
7792026-05-20T04:38:57.394ZMay 20 04:38:57.332 DEBG [sc] ox: logging in
7802026-05-20T04:38:57.445ZMay 20 04:38:57.410 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7812026-05-20T04:38:58.452ZMay 20 04:38:58.434 DEBG [sc] ox: starting
7822026-05-20T04:38:58.452ZMay 20 04:38:58.434 DEBG [sc] ox: connecting to [::1]:61527
7832026-05-20T04:38:58.486ZMay 20 04:38:58.434 DEBG [sc] ox waiting for prompt
7842026-05-20T04:38:58.487ZMay 20 04:38:58.434 DEBG [sc] ox: logging in
7852026-05-20T04:38:58.534ZMay 20 04:38:58.511 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7862026-05-20T04:38:58.907ZMay 20 04:38:58.887 DEBG [sc] ox: starting
7872026-05-20T04:38:58.907ZMay 20 04:38:58.887 DEBG [sc] ox: connecting to [::1]:61527
7882026-05-20T04:38:58.940ZMay 20 04:38:58.888 DEBG [sc] ox waiting for prompt
7892026-05-20T04:38:58.940ZMay 20 04:38:58.898 DEBG [sc] ox: logging in
7902026-05-20T04:38:59.000ZMay 20 04:38:58.976 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
7912026-05-20T04:38:59.097ZMay 20 04:38:59.042 DEBG [sc] ox: starting
7922026-05-20T04:38:59.097ZMay 20 04:38:59.042 DEBG [sc] ox: connecting to [::1]:61527
7932026-05-20T04:38:59.097ZMay 20 04:38:59.043 DEBG [sc] ox waiting for prompt
7942026-05-20T04:38:59.097ZMay 20 04:38:59.053 DEBG [sc] ox: logging in
7952026-05-20T04:38:59.148ZMay 20 04:38:59.130 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
7962026-05-20T04:38:59.203ZMay 20 04:38:59.185 DEBG [sc] ox: starting
7972026-05-20T04:38:59.203ZMay 20 04:38:59.185 DEBG [sc] ox: connecting to [::1]:61527
7982026-05-20T04:38:59.242ZMay 20 04:38:59.186 DEBG [sc] ox waiting for prompt
7992026-05-20T04:38:59.242ZMay 20 04:38:59.196 DEBG [sc] ox: logging in
8002026-05-20T04:38:59.296ZMay 20 04:38:59.273 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.0.1/24 tfportqsfp0_0/v4`
8012026-05-20T04:38:59.857ZMay 20 04:38:59.831 DEBG [sc] ox: starting
8022026-05-20T04:38:59.857ZMay 20 04:38:59.831 DEBG [sc] ox: connecting to [::1]:61527
8032026-05-20T04:38:59.894ZMay 20 04:38:59.832 DEBG [sc] ox waiting for prompt
8042026-05-20T04:38:59.894ZMay 20 04:38:59.842 DEBG [sc] ox: logging in
8052026-05-20T04:38:59.938ZMay 20 04:38:59.919 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v4 -p -o addr`
8062026-05-20T04:38:59.993ZMay 20 04:38:59.975 DEBG [sc] ox: starting
8072026-05-20T04:38:59.993ZMay 20 04:38:59.975 DEBG [sc] ox: connecting to [::1]:61527
8082026-05-20T04:39:00.026ZMay 20 04:38:59.975 DEBG [sc] ox waiting for prompt
8092026-05-20T04:39:00.026ZMay 20 04:38:59.985 DEBG [sc] ox: logging in
8102026-05-20T04:39:00.082ZMay 20 04:39:00.063 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:1::1/64 tfportqsfp0_0/v6`
8112026-05-20T04:39:00.595ZMay 20 04:39:00.577 DEBG [sc] ox: starting
8122026-05-20T04:39:00.595ZMay 20 04:39:00.577 DEBG [sc] ox: connecting to [::1]:61527
8132026-05-20T04:39:00.631ZMay 20 04:39:00.578 DEBG [sc] ox waiting for prompt
8142026-05-20T04:39:00.631ZMay 20 04:39:00.588 DEBG [sc] ox: logging in
8152026-05-20T04:39:00.688ZMay 20 04:39:00.666 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v6 -p -o addr`
8162026-05-20T04:39:00.745ZMay 20 04:39:00.722 DEBG [sc] ox: starting
8172026-05-20T04:39:00.745ZMay 20 04:39:00.722 DEBG [sc] ox: connecting to [::1]:61527
8182026-05-20T04:39:00.779ZMay 20 04:39:00.723 DEBG [sc] ox waiting for prompt
8192026-05-20T04:39:00.779ZMay 20 04:39:00.733 DEBG [sc] ox: logging in
8202026-05-20T04:39:00.831ZMay 20 04:39:00.810 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
8212026-05-20T04:39:00.883ZMay 20 04:39:00.865 DEBG [sc] ox: starting
8222026-05-20T04:39:00.883ZMay 20 04:39:00.865 DEBG [sc] ox: connecting to [::1]:61527
8232026-05-20T04:39:00.917ZMay 20 04:39:00.866 DEBG [sc] ox waiting for prompt
8242026-05-20T04:39:00.917ZMay 20 04:39:00.876 DEBG [sc] ox: logging in
8252026-05-20T04:39:00.972ZMay 20 04:39:00.954 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
8262026-05-20T04:39:01.034ZMay 20 04:39:01.010 DEBG [sc] ox: starting
8272026-05-20T04:39:01.034ZMay 20 04:39:01.010 DEBG [sc] ox: connecting to [::1]:61527
8282026-05-20T04:39:01.073ZMay 20 04:39:01.011 DEBG [sc] ox waiting for prompt
8292026-05-20T04:39:01.073ZMay 20 04:39:01.021 DEBG [sc] ox: logging in
8302026-05-20T04:39:01.124ZMay 20 04:39:01.098 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.1.1/24 tfportqsfp1_0/v4`
8312026-05-20T04:39:01.712ZMay 20 04:39:01.694 DEBG [sc] ox: starting
8322026-05-20T04:39:01.712ZMay 20 04:39:01.694 DEBG [sc] ox: connecting to [::1]:61527
8332026-05-20T04:39:01.744ZMay 20 04:39:01.695 DEBG [sc] ox waiting for prompt
8342026-05-20T04:39:01.744ZMay 20 04:39:01.705 DEBG [sc] ox: logging in
8352026-05-20T04:39:01.816ZMay 20 04:39:01.782 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v4 -p -o addr`
8362026-05-20T04:39:01.866ZMay 20 04:39:01.849 DEBG [sc] ox: starting
8372026-05-20T04:39:01.866ZMay 20 04:39:01.849 DEBG [sc] ox: connecting to [::1]:61527
8382026-05-20T04:39:01.905ZMay 20 04:39:01.850 DEBG [sc] ox waiting for prompt
8392026-05-20T04:39:01.906ZMay 20 04:39:01.859 DEBG [sc] ox: logging in
8402026-05-20T04:39:01.955ZMay 20 04:39:01.937 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:2::1/64 tfportqsfp1_0/v6`
8412026-05-20T04:39:02.475ZMay 20 04:39:02.449 DEBG [sc] ox: starting
8422026-05-20T04:39:02.475ZMay 20 04:39:02.449 DEBG [sc] ox: connecting to [::1]:61527
8432026-05-20T04:39:02.507ZMay 20 04:39:02.450 DEBG [sc] ox waiting for prompt
8442026-05-20T04:39:02.507ZMay 20 04:39:02.460 DEBG [sc] ox: logging in
8452026-05-20T04:39:02.563ZMay 20 04:39:02.537 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v6 -p -o addr`
8462026-05-20T04:39:02.623ZMay 20 04:39:02.603 DEBG [sc] ox: starting
8472026-05-20T04:39:02.623ZMay 20 04:39:02.603 DEBG [sc] ox: connecting to [::1]:61527
8482026-05-20T04:39:02.659ZMay 20 04:39:02.604 DEBG [sc] ox waiting for prompt
8492026-05-20T04:39:02.659ZMay 20 04:39:02.614 DEBG [sc] ox: logging in
8502026-05-20T04:39:02.712ZMay 20 04:39:02.692 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
8512026-05-20T04:39:02.771ZMay 20 04:39:02.748 DEBG [sc] ox: starting
8522026-05-20T04:39:02.771ZMay 20 04:39:02.748 DEBG [sc] ox: connecting to [::1]:61527
8532026-05-20T04:39:02.809ZMay 20 04:39:02.749 DEBG [sc] ox waiting for prompt
8542026-05-20T04:39:02.810ZMay 20 04:39:02.759 DEBG [sc] ox: logging in
8552026-05-20T04:39:02.857ZMay 20 04:39:02.836 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
8562026-05-20T04:39:02.926ZMay 20 04:39:02.907 INFO installing static v4 route 192.168.100.0/24
8572026-05-20T04:39:02.960ZMay 20 04:39:02.908 INFO installing static v6 route fd01::/64
8582026-05-20T04:39:02.960ZMay 20 04:39:02.909 INFO adding BFD peers for cr1 and cr2 (dual-stack)
8592026-05-20T04:39:02.960ZMay 20 04:39:02.911 INFO phase 1: both peers up
8602026-05-20T04:39:03.937ZMay 20 04:39:03.915 INFO cr1: executing frr script show bfd peers json
8612026-05-20T04:39:03.978ZMay 20 04:39:03.915 DEBG [sc] cr1: starting
8622026-05-20T04:39:03.978ZMay 20 04:39:03.915 DEBG [sc] cr1: connecting to [::1]:36148
8632026-05-20T04:39:03.978ZMay 20 04:39:03.916 DEBG [sc] cr1 waiting for prompt
8642026-05-20T04:39:03.978ZMay 20 04:39:03.927 DEBG [sc] cr1: logging in
8652026-05-20T04:39:04.325ZMay 20 04:39:04.307 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8662026-05-20T04:39:06.462ZMay 20 04:39:06.444 INFO cr1: executing frr script show bfd peers json
8672026-05-20T04:39:06.462ZMay 20 04:39:06.444 DEBG [sc] cr1: starting
8682026-05-20T04:39:06.462ZMay 20 04:39:06.444 DEBG [sc] cr1: connecting to [::1]:36148
8692026-05-20T04:39:06.504ZMay 20 04:39:06.445 DEBG [sc] cr1 waiting for prompt
8702026-05-20T04:39:06.504ZMay 20 04:39:06.455 DEBG [sc] cr1: logging in
8712026-05-20T04:39:06.611ZMay 20 04:39:06.587 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8722026-05-20T04:39:08.759ZMay 20 04:39:08.731 INFO cr2: executing eos script show bfd peers | json
8732026-05-20T04:39:08.759ZMay 20 04:39:08.731 DEBG [sc] cr2: starting
8742026-05-20T04:39:08.759ZMay 20 04:39:08.731 DEBG [sc] cr2: connecting to [::1]:40160
8752026-05-20T04:39:08.793ZMay 20 04:39:08.732 DEBG [sc] cr2 waiting for prompt
8762026-05-20T04:39:08.793ZMay 20 04:39:08.744 DEBG [sc] cr2: logging in
8772026-05-20T04:39:09.102ZMay 20 04:39:09.052 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8782026-05-20T04:39:11.446ZMay 20 04:39:11.413 INFO cr2: executing eos script show bfd peers | json
8792026-05-20T04:39:11.447ZMay 20 04:39:11.413 DEBG [sc] cr2: starting
8802026-05-20T04:39:11.447ZMay 20 04:39:11.413 DEBG [sc] cr2: connecting to [::1]:40160
8812026-05-20T04:39:11.484ZMay 20 04:39:11.414 DEBG [sc] cr2 waiting for prompt
8822026-05-20T04:39:11.484ZMay 20 04:39:11.423 DEBG [sc] cr2: logging in
8832026-05-20T04:39:11.580ZMay 20 04:39:11.556 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8842026-05-20T04:39:13.931ZMay 20 04:39:13.914 INFO phase 2: pause bfdd on cr1
8852026-05-20T04:39:13.931ZMay 20 04:39:13.914 INFO cr1: pausing frr bfdd
8862026-05-20T04:39:13.931ZMay 20 04:39:13.914 DEBG [sc] cr1: starting
8872026-05-20T04:39:13.931ZMay 20 04:39:13.914 DEBG [sc] cr1: connecting to [::1]:36148
8882026-05-20T04:39:13.964ZMay 20 04:39:13.915 DEBG [sc] cr1 waiting for prompt
8892026-05-20T04:39:13.964ZMay 20 04:39:13.925 DEBG [sc] cr1: logging in
8902026-05-20T04:39:14.096ZMay 20 04:39:14.058 DEBG [sc] cr1: executing command `pkill -STOP bfdd`
8912026-05-20T04:39:16.159ZMay 20 04:39:16.136 INFO cr2: executing eos script show bfd peers | json
8922026-05-20T04:39:16.159ZMay 20 04:39:16.136 DEBG [sc] cr2: starting
8932026-05-20T04:39:16.159ZMay 20 04:39:16.136 DEBG [sc] cr2: connecting to [::1]:40160
8942026-05-20T04:39:16.196ZMay 20 04:39:16.136 DEBG [sc] cr2 waiting for prompt
8952026-05-20T04:39:16.196ZMay 20 04:39:16.147 DEBG [sc] cr2: logging in
8962026-05-20T04:39:16.318ZMay 20 04:39:16.291 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8972026-05-20T04:39:18.638ZMay 20 04:39:18.616 INFO cr2: executing eos script show bfd peers | json
8982026-05-20T04:39:18.638ZMay 20 04:39:18.616 DEBG [sc] cr2: starting
8992026-05-20T04:39:18.638ZMay 20 04:39:18.616 DEBG [sc] cr2: connecting to [::1]:40160
9002026-05-20T04:39:18.670ZMay 20 04:39:18.617 DEBG [sc] cr2 waiting for prompt
9012026-05-20T04:39:18.670ZMay 20 04:39:18.627 DEBG [sc] cr2: logging in
9022026-05-20T04:39:18.782ZMay 20 04:39:18.760 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9032026-05-20T04:39:21.105ZMay 20 04:39:21.081 INFO phase 3: pause ceos on cr2
9042026-05-20T04:39:21.105ZMay 20 04:39:21.081 INFO cr2: pausing ceos
9052026-05-20T04:39:21.105ZMay 20 04:39:21.081 DEBG [sc] cr2: starting
9062026-05-20T04:39:21.105ZMay 20 04:39:21.081 DEBG [sc] cr2: connecting to [::1]:40160
9072026-05-20T04:39:21.139ZMay 20 04:39:21.082 DEBG [sc] cr2 waiting for prompt
9082026-05-20T04:39:21.139ZMay 20 04:39:21.091 DEBG [sc] cr2: logging in
9092026-05-20T04:39:21.258ZMay 20 04:39:21.235 DEBG [sc] cr2: executing command `docker pause ceos`
9102026-05-20T04:39:23.375ZMay 20 04:39:23.344 INFO phase 4: resume bfdd on cr1
9112026-05-20T04:39:23.375ZMay 20 04:39:23.344 INFO cr1: resuming frr bfdd
9122026-05-20T04:39:23.375ZMay 20 04:39:23.344 DEBG [sc] cr1: starting
9132026-05-20T04:39:23.375ZMay 20 04:39:23.344 DEBG [sc] cr1: connecting to [::1]:36148
9142026-05-20T04:39:23.408ZMay 20 04:39:23.345 DEBG [sc] cr1 waiting for prompt
9152026-05-20T04:39:23.408ZMay 20 04:39:23.356 DEBG [sc] cr1: logging in
9162026-05-20T04:39:23.506ZMay 20 04:39:23.488 DEBG [sc] cr1: executing command `pkill -CONT bfdd`
9172026-05-20T04:39:25.594ZMay 20 04:39:25.576 INFO cr1: executing frr script show bfd peers json
9182026-05-20T04:39:25.594ZMay 20 04:39:25.576 DEBG [sc] cr1: starting
9192026-05-20T04:39:25.594ZMay 20 04:39:25.576 DEBG [sc] cr1: connecting to [::1]:36148
9202026-05-20T04:39:25.627ZMay 20 04:39:25.576 DEBG [sc] cr1 waiting for prompt
9212026-05-20T04:39:25.627ZMay 20 04:39:25.585 DEBG [sc] cr1: logging in
9222026-05-20T04:39:25.746ZMay 20 04:39:25.728 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9232026-05-20T04:39:27.887ZMay 20 04:39:27.868 INFO cr1: executing frr script show bfd peers json
9242026-05-20T04:39:27.887ZMay 20 04:39:27.868 DEBG [sc] cr1: starting
9252026-05-20T04:39:27.887ZMay 20 04:39:27.868 DEBG [sc] cr1: connecting to [::1]:36148
9262026-05-20T04:39:27.927ZMay 20 04:39:27.869 DEBG [sc] cr1 waiting for prompt
9272026-05-20T04:39:27.927ZMay 20 04:39:27.879 DEBG [sc] cr1: logging in
9282026-05-20T04:39:28.039ZMay 20 04:39:28.022 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9292026-05-20T04:39:30.303ZMay 20 04:39:30.153 INFO phase 5: unpause ceos on cr2
9302026-05-20T04:39:30.303ZMay 20 04:39:30.153 INFO cr2: unpausing ceos
9312026-05-20T04:39:30.303ZMay 20 04:39:30.153 DEBG [sc] cr2: starting
9322026-05-20T04:39:30.303ZMay 20 04:39:30.153 DEBG [sc] cr2: connecting to [::1]:40160
9332026-05-20T04:39:30.344ZMay 20 04:39:30.154 DEBG [sc] cr2 waiting for prompt
9342026-05-20T04:39:30.344ZMay 20 04:39:30.164 DEBG [sc] cr2: logging in
9352026-05-20T04:39:30.344ZMay 20 04:39:30.285 DEBG [sc] cr2: executing command `docker unpause ceos`
9362026-05-20T04:39:32.483ZMay 20 04:39:32.396 INFO cr1: executing frr script show bfd peers json
9372026-05-20T04:39:32.483ZMay 20 04:39:32.396 DEBG [sc] cr1: starting
9382026-05-20T04:39:32.483ZMay 20 04:39:32.396 DEBG [sc] cr1: connecting to [::1]:36148
9392026-05-20T04:39:32.522ZMay 20 04:39:32.397 DEBG [sc] cr1 waiting for prompt
9402026-05-20T04:39:32.522ZMay 20 04:39:32.408 DEBG [sc] cr1: logging in
9412026-05-20T04:39:32.558ZMay 20 04:39:32.540 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9422026-05-20T04:39:34.700ZMay 20 04:39:34.680 INFO cr1: executing frr script show bfd peers json
9432026-05-20T04:39:34.700ZMay 20 04:39:34.680 DEBG [sc] cr1: starting
9442026-05-20T04:39:34.700ZMay 20 04:39:34.680 DEBG [sc] cr1: connecting to [::1]:36148
9452026-05-20T04:39:34.733ZMay 20 04:39:34.681 DEBG [sc] cr1 waiting for prompt
9462026-05-20T04:39:34.733ZMay 20 04:39:34.690 DEBG [sc] cr1: logging in
9472026-05-20T04:39:34.830ZMay 20 04:39:34.811 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9482026-05-20T04:39:36.968ZMay 20 04:39:36.949 INFO cr2: executing eos script show bfd peers | json
9492026-05-20T04:39:36.968ZMay 20 04:39:36.950 DEBG [sc] cr2: starting
9502026-05-20T04:39:37.005ZMay 20 04:39:36.950 DEBG [sc] cr2: connecting to [::1]:40160
9512026-05-20T04:39:37.005ZMay 20 04:39:36.950 DEBG [sc] cr2 waiting for prompt
9522026-05-20T04:39:37.005ZMay 20 04:39:36.962 DEBG [sc] cr2: logging in
9532026-05-20T04:39:37.111ZMay 20 04:39:37.094 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9542026-05-20T04:39:39.441ZMay 20 04:39:39.423 INFO cr2: executing eos script show bfd peers | json
9552026-05-20T04:39:39.477ZMay 20 04:39:39.423 DEBG [sc] cr2: starting
9562026-05-20T04:39:39.477ZMay 20 04:39:39.423 DEBG [sc] cr2: connecting to [::1]:40160
9572026-05-20T04:39:39.477ZMay 20 04:39:39.424 DEBG [sc] cr2 waiting for prompt
9582026-05-20T04:39:39.478ZMay 20 04:39:39.433 DEBG [sc] cr2: logging in
9592026-05-20T04:39:39.595ZMay 20 04:39:39.577 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9602026-05-20T04:39:41.933ZMay 20 04:39:41.915 INFO trio bfd static routing test passed 🎉
9612026-05-20T04:39:41.933ZMay 20 04:39:41.915 INFO destroying runner for deployment mgtriobfd
9622026-05-20T04:39:41.933ZMay 20 04:39:41.915 INFO destroying deployment mgtriobfd
9632026-05-20T04:39:41.933ZMay 20 04:39:41.915 INFO destroying nodes
9642026-05-20T04:39:42.056ZMay 20 04:39:42.030 INFO destroying links
9652026-05-20T04:39:42.056ZMay 20 04:39:42.030 INFO destroying link mgtriobfd_ox_sn_vnic0
9662026-05-20T04:39:42.097ZMay 20 04:39:42.032 INFO destroying link mgtriobfd_ox_sn_sim0
9672026-05-20T04:39:42.097ZMay 20 04:39:42.033 INFO destroying link mgtriobfd_cr1_vn_vnic0
9682026-05-20T04:39:43.057ZMay 20 04:39:43.035 INFO destroying link mgtriobfd_cr1_vn_sim0
9692026-05-20T04:39:43.089ZMay 20 04:39:43.036 INFO destroying link mgtriobfd_ox_sn_vnic1
9702026-05-20T04:39:43.089ZMay 20 04:39:43.037 INFO destroying link mgtriobfd_ox_sn_sim1
9712026-05-20T04:39:43.089ZMay 20 04:39:43.038 INFO destroying link mgtriobfd_cr2_vn_vnic0
9722026-05-20T04:39:43.089ZMay 20 04:39:43.039 INFO destroying link mgtriobfd_cr2_vn_sim0
9732026-05-20T04:39:43.089ZMay 20 04:39:43.040 INFO destroying external links
9742026-05-20T04:39:43.089ZMay 20 04:39:43.040 INFO destroying external link mgtriobfd_ox_vn_vnic2
9752026-05-20T04:39:43.089ZMay 20 04:39:43.041 INFO destroying external link mgtriobfd_cr1_vn_vnic1
9762026-05-20T04:39:43.089ZMay 20 04:39:43.042 INFO destroying external link mgtriobfd_cr2_vn_vnic1
9772026-05-20T04:39:43.089ZMay 20 04:39:43.043 INFO destroying images
9782026-05-20T04:39:43.555ZMay 20 04:39:43.533 INFO destroying workspace at .falcon
9792026-05-20T04:39:43.592Zprocess exited: duration 909069 ms, exit code 0
 
9802026-05-20T04:39:43.661Zfound 0 output files