01KRAK5A92RZNX45HGJ57KJVGH: falcon

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

Buildomat Job: 01KRAK5NXNVRB52XHDXP248Z0W

Tags:

Output:

SEQ GLOBAL TIME DETAILS
12026-05-11T04:15:36.086Zjob dependencies complete; ready to run (waiting for 13 m 41 s)
22026-05-11T04:18:49.397Zjob assigned to worker 01KRAKYRQ4WEPX93Y3WA1BW7EQ [factory edgar, gimlet/BRM42220010/946] (queued for 3 m 13 s)
32026-05-11T04:18:50.452Zdownloading input: /input/build/work/debug/ddmadm
42026-05-11T04:19:13.207Zdownloaded input: /input/build/work/debug/ddmadm
52026-05-11T04:19:13.207Zdownloading input: /input/build/work/debug/ddmd
62026-05-11T04:19:41.232Zdownloaded input: /input/build/work/debug/ddmd
72026-05-11T04:19:41.232Zdownloading input: /input/build/work/debug/mgadm
82026-05-11T04:20:07.522Zdownloaded input: /input/build/work/debug/mgadm
92026-05-11T04:20:07.522Zdownloading input: /input/build/work/debug/mgd
102026-05-11T04:20:38.847Zdownloaded input: /input/build/work/debug/mgd
112026-05-11T04:20:38.871Zdownloading input: /input/build/work/release/ddmadm
122026-05-11T04:20:40.934Zdownloaded input: /input/build/work/release/ddmadm
132026-05-11T04:20:40.934Zdownloading input: /input/build/work/release/ddmd
142026-05-11T04:20:43.585Zdownloaded input: /input/build/work/release/ddmd
152026-05-11T04:20:43.585Zdownloading input: /input/build/work/release/falcon-lab
162026-05-11T04:20:45.266Zdownloaded input: /input/build/work/release/falcon-lab
172026-05-11T04:20:45.266Zdownloading input: /input/build/work/release/mgadm
182026-05-11T04:20:47.845Zdownloaded input: /input/build/work/release/mgadm
192026-05-11T04:20:47.845Zdownloading input: /input/build/work/release/mgd
202026-05-11T04:20:51.197Zdownloaded input: /input/build/work/release/mgd
212026-05-11T04:20:51.221Zdownloading input: /input/build-interop/work/testbed.tar.gz
222026-05-11T04:20:59.978Zdownloaded input: /input/build-interop/work/testbed.tar.gz
232026-05-11T04:20:59.978Zdownloading input: /input/build-interop/work/dhcp-server
242026-05-11T04:21:02.238Zdownloaded input: /input/build-interop/work/dhcp-server
 
252026-05-11T04:21:02.238Zstarting task 0: "setup"
262026-05-11T04:21:02.263Z++ uname -s
272026-05-11T04:21:02.263Z+ kern=SunOS
282026-05-11T04:21:02.263Z+ build_user=build
292026-05-11T04:21:02.263Z+ build_uid=12345
302026-05-11T04:21:02.263Z+ work_dir=/work
312026-05-11T04:21:02.263Z+ input_dir=/input
322026-05-11T04:21:02.263Z+ [[ 0 == 12345 ]]
332026-05-11T04:21:02.263Z+ case "$kern" in
342026-05-11T04:21:02.263Z+ groupadd -g 12345 build
352026-05-11T04:21:02.287Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
362026-05-11T04:21:04.275Z+ zfs create -o mountpoint=/work rpool/work
372026-05-11T04:21:05.298Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
382026-05-11T04:21:05.322Z+ home_fs=
392026-05-11T04:21:05.322Z+ [[ '' == autofs ]]
402026-05-11T04:21:05.322Z+ mkdir -p /home/build
412026-05-11T04:21:05.322Z+ chown build:build /home/build /work
422026-05-11T04:21:06.311Z+ chmod 0700 /home/build /work
432026-05-11T04:21:06.336Zprocess exited: duration 4077 ms, exit code 0
 
442026-05-11T04:21:06.384Zstarting task 1: "authentication"
452026-05-11T04:21:06.480Zprocess exited: duration 95 ms, exit code 0
 
462026-05-11T04:21:06.528Zstarting task 2: "build"
472026-05-11T04:21:06.553Z+ set -e
482026-05-11T04:21:06.553Z+ banner zpool
492026-05-11T04:21:06.553Z
502026-05-11T04:21:06.553Z ###### ##### #### #### #
512026-05-11T04:21:06.553Z # # # # # # # #
522026-05-11T04:21:06.553Z # # # # # # # #
532026-05-11T04:21:06.553Z # ##### # # # # #
542026-05-11T04:21:06.553Z # # # # # # #
552026-05-11T04:21:06.553Z ###### # #### #### ######
562026-05-11T04:21:06.553Z
572026-05-11T04:21:06.553Z++ pfexec diskinfo -pH
582026-05-11T04:21:06.578Z++ sort -k8 -n -r
592026-05-11T04:21:06.578Z++ head -1
602026-05-11T04:21:06.578Z++ awk '{print $2}'
612026-05-11T04:21:06.602Z+ DISK=c9t0014EE81000BC3B1d0
622026-05-11T04:21:06.602Z+ export DISK
632026-05-11T04:21:06.602Z+ pfexec zpool create -o ashift=12 -f cpool c9t0014EE81000BC3B1d0
642026-05-11T04:21:06.668Z+ pfexec zfs create -o mountpoint=/ci cpool/ci
652026-05-11T04:21:06.696Z++ curl -s http://catacomb.eng.oxide.computer:12346/trim-me
662026-05-11T04:21:06.868Z+ [[ true =~ true ]]
672026-05-11T04:21:06.868Z+ pfexec zpool trim cpool
682026-05-11T04:21:06.892Z++ zpool status -t cpool
692026-05-11T04:21:06.917Z+ [[ ! pool: cpool
702026-05-11T04:21:06.917Z state: ONLINE
712026-05-11T04:21:06.917Z scan: none requested
722026-05-11T04:21:06.917Zconfig:
732026-05-11T04:21:06.917Z
742026-05-11T04:21:06.917Z NAME STATE READ WRITE CKSUM
752026-05-11T04:21:06.917Z cpool ONLINE 0 0 0
762026-05-11T04:21:06.917Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (1% trimmed, started at May 11, 2026 at 04:21:06 AM UTC)
772026-05-11T04:21:06.917Z
782026-05-11T04:21:06.917Zerrors: No known data errors =~ 100% ]]
792026-05-11T04:21:06.917Z+ sleep 10
802026-05-11T04:21:16.903Z++ zpool status -t cpool
812026-05-11T04:21:16.927Z+ [[ ! pool: cpool
822026-05-11T04:21:16.927Z state: ONLINE
832026-05-11T04:21:16.927Z scan: none requested
842026-05-11T04:21:16.927Zconfig:
852026-05-11T04:21:16.927Z
862026-05-11T04:21:16.927Z NAME STATE READ WRITE CKSUM
872026-05-11T04:21:16.927Z cpool ONLINE 0 0 0
882026-05-11T04:21:16.927Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (73% trimmed, started at May 11, 2026 at 04:21:06 AM UTC)
892026-05-11T04:21:16.927Z
902026-05-11T04:21:16.927Zerrors: No known data errors =~ 100% ]]
912026-05-11T04:21:16.927Z+ sleep 10
922026-05-11T04:21:26.917Z++ zpool status -t cpool
932026-05-11T04:21:26.942Z+ [[ ! pool: cpool
942026-05-11T04:21:26.942Z state: ONLINE
952026-05-11T04:21:26.942Z scan: none requested
962026-05-11T04:21:26.942Zconfig:
972026-05-11T04:21:26.942Z
982026-05-11T04:21:26.942Z NAME STATE READ WRITE CKSUM
992026-05-11T04:21:26.942Z cpool ONLINE 0 0 0
1002026-05-11T04:21:26.942Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (100% trimmed, completed at May 11, 2026 at 04:21:20 AM UTC)
1012026-05-11T04:21:26.942Z
1022026-05-11T04:21:26.942Zerrors: No known data errors =~ 100% ]]
1032026-05-11T04:21:26.942Z+ pfexec chown 12345 /ci
1042026-05-11T04:21:26.942Z+ cd /ci
1052026-05-11T04:21:26.942Z+ export FALCON_DATASET=cpool/falcon
1062026-05-11T04:21:26.942Z+ FALCON_DATASET=cpool/falcon
1072026-05-11T04:21:26.942Z+ banner setup
1082026-05-11T04:21:26.942Z
1092026-05-11T04:21:26.942Z #### ###### ##### # # #####
1102026-05-11T04:21:26.942Z # # # # # # #
1112026-05-11T04:21:26.942Z #### ##### # # # # #
1122026-05-11T04:21:26.942Z # # # # # #####
1132026-05-11T04:21:26.942Z # # # # # # #
1142026-05-11T04:21:26.942Z #### ###### # #### #
1152026-05-11T04:21:26.942Z
1162026-05-11T04:21:26.942Z+ cp /input/build-interop/work/dhcp-server .
1172026-05-11T04:21:26.967Z+ cp /input/build/work/release/falcon-lab .
1182026-05-11T04:21:27.015Z+ cp /input/build/work/release/mgd .
1192026-05-11T04:21:27.095Z+ cp /input/build/work/release/ddmd .
1202026-05-11T04:21:27.180Z+ chmod +x dhcp-server falcon-lab mgd ddmd
1212026-05-11T04:21:27.204Z+ mkdir -p cargo-bay
1222026-05-11T04:21:27.204Z+ mv mgd cargo-bay/
1232026-05-11T04:21:27.204Z+ mv ddmd cargo-bay/
1242026-05-11T04:21:27.204Z+ export EXT_INTERFACE=igb0
1252026-05-11T04:21:27.204Z+ EXT_INTERFACE=igb0
1262026-05-11T04:21:27.204Z++ bmat address ls -f extra -Ho first
1272026-05-11T04:21:27.228Z+ first=10.151.6.164
1282026-05-11T04:21:27.228Z++ bmat address ls -f extra -Ho last
1292026-05-11T04:21:27.252Z+ last=10.151.6.227
1302026-05-11T04:21:27.252Z++ bmat address ls -f extra -Ho gateway
1312026-05-11T04:21:27.277Z+ gw=10.151.6.1
1322026-05-11T04:21:27.277Z++ ipadm show-addr igb0/dhcp -po ADDR
1332026-05-11T04:21:27.301Z++ sed 's#/.*##g'
1342026-05-11T04:21:27.301Z+ server=10.151.6.100
1352026-05-11T04:21:27.301Z+ RUST_LOG=debug
1362026-05-11T04:21:27.301Z+ pfexec ./falcon-lab run trio-unnumbered
1372026-05-11T04:21:27.301Z+ pfexec ./dhcp-server 10.151.6.164 10.151.6.227 10.151.6.1 10.151.6.100
1382026-05-11T04:21:27.326ZMay 11 04:21:27.288 DEBG using default route interface igb0
1392026-05-11T04:21:27.326ZMay 11 04:21:27.288 DEBG using default route interface igb0
1402026-05-11T04:21:27.326ZMay 11 04:21:27.288 DEBG using default route interface igb0
1412026-05-11T04:21:27.326ZMay 11 04:21:27.288 INFO launching runner: deployment(mgtriou) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
1422026-05-11T04:21:27.326ZMay 11 04:21:27.288 INFO starting preflight for deployment mgtriou
1432026-05-11T04:21:27.326ZMay 11 04:21:27.288 INFO propolis-server binary not found
1442026-05-11T04:21:27.326ZMay 11 04:21:27.288 INFO downloading propolis server rev 36f20be9bb4c3b362029237f5feb6377c982395f, writing to .falcon/bin/propolis-server
1452026-05-11T04:21:31.071ZMay 11 04:21:31.055 INFO ovmf fd not found
1462026-05-11T04:21:31.071ZMay 11 04:21:31.055 INFO downloading ovmf
1472026-05-11T04:21:31.523ZMay 11 04:21:31.508 INFO base image for helios-2.9 does not exist, attempting to install
1482026-05-11T04:21:31.523ZMay 11 04:21:31.508 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/helios-2.9_0.raw.xz
1492026-05-11T04:22:08.998ZMay 11 04:22:08.985 INFO extracting image to /tmp/helios-2.9_0.raw
1502026-05-11T04:22:42.943ZMay 11 04:22:42.929 INFO creating zvol cpool/falcon/img/helios-2.9 of size 4508880896
1512026-05-11T04:22:42.992ZMay 11 04:22:42.980 INFO copying image data to zvol
1522026-05-11T04:22:53.401ZMay 11 04:22:53.388 INFO creating zfs snapshot cpool/falcon/img/helios-2.9@base
1532026-05-11T04:22:58.078ZMay 11 04:22:58.066 INFO base image for debian-13.2 does not exist, attempting to install
1542026-05-11T04:22:58.078ZMay 11 04:22:58.066 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz
1552026-05-11T04:23:25.276ZMay 11 04:23:25.263 INFO extracting image to /tmp/debian-13.2_0.raw
1562026-05-11T04:23:46.482ZMay 11 04:23:46.469 INFO creating zvol cpool/falcon/img/debian-13.2 of size 3221229568
1572026-05-11T04:23:46.507ZMay 11 04:23:46.495 INFO copying image data to zvol
1582026-05-11T04:23:53.477ZMay 11 04:23:53.465 INFO creating zfs snapshot cpool/falcon/img/debian-13.2@base
1592026-05-11T04:23:57.201ZMay 11 04:23:57.189 INFO base image for eos-4.35 does not exist, attempting to install
1602026-05-11T04:23:57.201ZMay 11 04:23:57.189 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz
1612026-05-11T04:24:55.547ZMay 11 04:24:55.534 INFO extracting image to /tmp/eos-4.35_0.raw
1622026-05-11T04:26:20.024ZMay 11 04:26:20.011 INFO creating zvol cpool/falcon/img/eos-4.35 of size 21474840576
1632026-05-11T04:26:20.049ZMay 11 04:26:20.037 INFO copying image data to zvol
1642026-05-11T04:27:07.522ZMay 11 04:27:07.510 INFO creating zfs snapshot cpool/falcon/img/eos-4.35@base
1652026-05-11T04:27:10.984ZMay 11 04:27:10.972 INFO creating links
1662026-05-11T04:27:10.984ZMay 11 04:27:10.972 DEBG destroying link mgtriou_ox_sn_vnic0
1672026-05-11T04:27:11.009ZMay 11 04:27:10.972 DEBG destroying link mgtriou_ox_sn_sim0
1682026-05-11T04:27:11.009ZMay 11 04:27:10.972 INFO creating simnet link 'mgtriou_ox_sn_sim0'
1692026-05-11T04:27:11.009ZMay 11 04:27:10.974 INFO creating vnic link 'mgtriou_ox_sn_vnic0'
1702026-05-11T04:27:11.009ZMay 11 04:27:10.981 DEBG link pair created
1712026-05-11T04:27:11.009ZMay 11 04:27:10.981 DEBG destroying link mgtriou_cr1_vn_vnic0
1722026-05-11T04:27:11.009ZMay 11 04:27:10.981 DEBG destroying link mgtriou_cr1_vn_sim0
1732026-05-11T04:27:11.009ZMay 11 04:27:10.981 INFO creating simnet link 'mgtriou_cr1_vn_sim0'
1742026-05-11T04:27:11.009ZMay 11 04:27:10.982 INFO creating vnic link 'mgtriou_cr1_vn_vnic0'
1752026-05-11T04:27:11.009ZMay 11 04:27:10.989 DEBG link pair created
1762026-05-11T04:27:11.009ZMay 11 04:27:10.989 DEBG destroying link mgtriou_ox_sn_vnic1
1772026-05-11T04:27:11.009ZMay 11 04:27:10.989 DEBG destroying link mgtriou_ox_sn_sim1
1782026-05-11T04:27:11.009ZMay 11 04:27:10.989 INFO creating simnet link 'mgtriou_ox_sn_sim1'
1792026-05-11T04:27:11.009ZMay 11 04:27:10.990 INFO creating vnic link 'mgtriou_ox_sn_vnic1'
1802026-05-11T04:27:11.034ZMay 11 04:27:10.996 DEBG link pair created
1812026-05-11T04:27:11.034ZMay 11 04:27:10.996 DEBG destroying link mgtriou_cr2_vn_vnic0
1822026-05-11T04:27:11.034ZMay 11 04:27:10.996 DEBG destroying link mgtriou_cr2_vn_sim0
1832026-05-11T04:27:11.034ZMay 11 04:27:10.996 INFO creating simnet link 'mgtriou_cr2_vn_sim0'
1842026-05-11T04:27:11.034ZMay 11 04:27:10.997 INFO creating vnic link 'mgtriou_cr2_vn_vnic0'
1852026-05-11T04:27:11.034ZMay 11 04:27:11.004 DEBG link pair created
1862026-05-11T04:27:11.034ZMay 11 04:27:11.004 INFO creating external links
1872026-05-11T04:27:11.034ZMay 11 04:27:11.004 DEBG destroying external link mgtriou_ox_vn_vnic2
1882026-05-11T04:27:11.034ZMay 11 04:27:11.004 INFO creating external link mgtriou_ox_vn_vnic2
1892026-05-11T04:27:11.034ZMay 11 04:27:11.006 DEBG external link mgtriou_ox_vn_vnic2@igb0 created
1902026-05-11T04:27:11.034ZMay 11 04:27:11.006 DEBG destroying external link mgtriou_cr1_vn_vnic1
1912026-05-11T04:27:11.034ZMay 11 04:27:11.006 INFO creating external link mgtriou_cr1_vn_vnic1
1922026-05-11T04:27:11.034ZMay 11 04:27:11.007 DEBG external link mgtriou_cr1_vn_vnic1@igb0 created
1932026-05-11T04:27:11.034ZMay 11 04:27:11.007 DEBG destroying external link mgtriou_cr2_vn_vnic1
1942026-05-11T04:27:11.034ZMay 11 04:27:11.007 INFO creating external link mgtriou_cr2_vn_vnic1
1952026-05-11T04:27:11.034ZMay 11 04:27:11.008 DEBG external link mgtriou_cr2_vn_vnic1@igb0 created
1962026-05-11T04:27:11.034ZMay 11 04:27:11.008 INFO creating nodes
1972026-05-11T04:27:11.034ZMay 11 04:27:11.008 INFO ox: launching node
1982026-05-11T04:27:11.034ZMay 11 04:27:11.011 INFO cr1: launching node
1992026-05-11T04:27:11.034ZMay 11 04:27:11.012 INFO cr2: launching node
2002026-05-11T04:27:11.058ZMay 11 04:27:11.026 INFO launched instance ox with pid 854 on port 54791
2012026-05-11T04:27:11.059ZMay 11 04:27:11.026 INFO ox: instance ensure
2022026-05-11T04:27:11.059ZMay 11 04:27:11.026 INFO launched instance cr1 with pid 855 on port 34296
2032026-05-11T04:27:11.059ZMay 11 04:27:11.026 INFO cr1: instance ensure
2042026-05-11T04:27:11.059ZMay 11 04:27:11.027 INFO launched instance cr2 with pid 856 on port 46204
2052026-05-11T04:27:11.059ZMay 11 04:27:11.027 INFO cr2: instance ensure
2062026-05-11T04:27:13.319ZMay 11 04:27:13.306 INFO cr2: instance run
2072026-05-11T04:27:13.343ZMay 11 04:27:13.307 DEBG [sc] cr2: starting
2082026-05-11T04:27:13.343ZMay 11 04:27:13.307 DEBG [sc] cr2: connecting to [::1]:46204
2092026-05-11T04:27:13.343ZMay 11 04:27:13.308 DEBG [sc] cr2 waiting for prompt
2102026-05-11T04:27:13.436ZMay 11 04:27:13.424 INFO ox: instance run
2112026-05-11T04:27:13.460ZMay 11 04:27:13.424 DEBG [sc] ox: starting
2122026-05-11T04:27:13.460ZMay 11 04:27:13.424 DEBG [sc] ox: connecting to [::1]:54791
2132026-05-11T04:27:13.460ZMay 11 04:27:13.425 DEBG [sc] ox waiting for prompt
2142026-05-11T04:27:13.484ZMay 11 04:27:13.465 INFO cr1: instance run
2152026-05-11T04:27:13.484ZMay 11 04:27:13.465 DEBG [sc] cr1: starting
2162026-05-11T04:27:13.484ZMay 11 04:27:13.465 DEBG [sc] cr1: connecting to [::1]:34296
2172026-05-11T04:27:13.484ZMay 11 04:27:13.466 DEBG [sc] cr1 waiting for prompt
2182026-05-11T04:27:30.532ZMay 11 04:27:30.518 DEBG [sc] cr1: logging in
2192026-05-11T04:27:30.927ZMay 11 04:27:30.914 INFO cr1: mounting /opt/cargo-bay
2202026-05-11T04:27:30.927ZMay 11 04:27:30.914 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2212026-05-11T04:27:30.952ZMay 11 04:27:30.936 DEBG [sc] cr1: executing command `cd`
2222026-05-11T04:27:30.976ZMay 11 04:27:30.947 INFO cr1: finished mounting /opt/cargo-bay
2232026-05-11T04:27:30.976ZMay 11 04:27:30.947 DEBG [sc] cr1: executing command `hostname cr1`
2242026-05-11T04:27:30.976ZMay 11 04:27:30.958 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
2252026-05-11T04:27:31.000ZMay 11 04:27:30.970 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
2262026-05-11T04:27:31.000ZMay 11 04:27:30.980 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
2272026-05-11T04:27:31.024ZMay 11 04:27:30.991 INFO cr1: logging out
2282026-05-11T04:27:33.063ZMay 11 04:27:33.050 INFO cr1: logged out
2292026-05-11T04:27:34.143ZMay 11 04:27:34.129 DEBG [sc] ox: logging in
2302026-05-11T04:27:34.318ZMay 11 04:27:34.304 INFO ox: mounting /opt/cargo-bay
2312026-05-11T04:27:34.318ZMay 11 04:27:34.304 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2322026-05-11T04:27:34.997ZMay 11 04:27:34.984 DEBG [sc] cr2: logging in
2332026-05-11T04:27:35.313ZMay 11 04:27:35.299 DEBG [sc] ox: executing command `cd`
2342026-05-11T04:27:35.337ZMay 11 04:27:35.310 INFO ox: finished mounting /opt/cargo-bay
2352026-05-11T04:27:35.337ZMay 11 04:27:35.310 DEBG [sc] ox: executing command `hostname ox`
2362026-05-11T04:27:35.337ZMay 11 04:27:35.322 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
2372026-05-11T04:27:35.361ZMay 11 04:27:35.332 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
2382026-05-11T04:27:35.361ZMay 11 04:27:35.343 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
2392026-05-11T04:27:35.386ZMay 11 04:27:35.354 INFO ox: logging out
2402026-05-11T04:27:35.427ZMay 11 04:27:35.414 INFO cr2: mounting /opt/cargo-bay
2412026-05-11T04:27:35.427ZMay 11 04:27:35.414 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2422026-05-11T04:27:35.476ZMay 11 04:27:35.431 INFO ox: logged out
2432026-05-11T04:27:35.476ZMay 11 04:27:35.436 DEBG [sc] cr2: executing command `cd`
2442026-05-11T04:27:35.476ZMay 11 04:27:35.446 INFO cr2: finished mounting /opt/cargo-bay
2452026-05-11T04:27:35.476ZMay 11 04:27:35.446 DEBG [sc] cr2: executing command `hostname cr2`
2462026-05-11T04:27:35.476ZMay 11 04:27:35.457 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
2472026-05-11T04:27:35.501ZMay 11 04:27:35.468 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
2482026-05-11T04:27:35.501ZMay 11 04:27:35.480 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
2492026-05-11T04:27:35.525ZMay 11 04:27:35.491 INFO cr2: logging out
2502026-05-11T04:27:38.482ZMay 11 04:27:38.468 INFO cr2: logged out
2512026-05-11T04:27:38.506ZMay 11 04:27:38.469 DEBG [sc] ox: starting
2522026-05-11T04:27:38.506ZMay 11 04:27:38.469 DEBG [sc] ox: connecting to [::1]:54791
2532026-05-11T04:27:38.506ZMay 11 04:27:38.469 DEBG [sc] ox waiting for prompt
2542026-05-11T04:27:38.506ZMay 11 04:27:38.480 DEBG [sc] ox: logging in
2552026-05-11T04:27:38.582ZMay 11 04:27:38.569 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
2562026-05-11T04:27:44.607ZMay 11 04:27:44.594 DEBG [sc] ox: starting
2572026-05-11T04:27:44.608ZMay 11 04:27:44.594 DEBG [sc] ox: connecting to [::1]:54791
2582026-05-11T04:27:44.632ZMay 11 04:27:44.594 DEBG [sc] ox waiting for prompt
2592026-05-11T04:27:44.632ZMay 11 04:27:44.605 DEBG [sc] ox: logging in
2602026-05-11T04:27:44.706ZMay 11 04:27:44.693 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
2612026-05-11T04:27:44.794ZMay 11 04:27:44.780 DEBG [sc] ox: starting
2622026-05-11T04:27:44.794ZMay 11 04:27:44.780 DEBG [sc] ox: connecting to [::1]:54791
2632026-05-11T04:27:44.819ZMay 11 04:27:44.781 DEBG [sc] ox waiting for prompt
2642026-05-11T04:27:44.819ZMay 11 04:27:44.792 DEBG [sc] ox: logging in
2652026-05-11T04:27:44.893ZMay 11 04:27:44.880 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
2662026-05-11T04:27:44.960ZMay 11 04:27:44.947 INFO cr1: installing frr
2672026-05-11T04:27:44.960ZMay 11 04:27:44.947 INFO waiting for ceos to initialize
2682026-05-11T04:27:44.960ZMay 11 04:27:44.947 INFO ox: setting up npuvm
2692026-05-11T04:27:44.985ZMay 11 04:27:44.947 DEBG [sc] cr1: starting
2702026-05-11T04:27:44.985ZMay 11 04:27:44.947 DEBG [sc] cr1: connecting to [::1]:34296
2712026-05-11T04:27:44.985ZMay 11 04:27:44.947 DEBG [sc] cr2: starting
2722026-05-11T04:27:44.985ZMay 11 04:27:44.947 DEBG [sc] cr2: connecting to [::1]:46204
2732026-05-11T04:27:44.985ZMay 11 04:27:44.947 DEBG [sc] ox: starting
2742026-05-11T04:27:44.985ZMay 11 04:27:44.947 DEBG [sc] ox: connecting to [::1]:54791
2752026-05-11T04:27:44.985ZMay 11 04:27:44.947 DEBG [sc] ox waiting for prompt
2762026-05-11T04:27:44.985ZMay 11 04:27:44.947 DEBG [sc] cr2 waiting for prompt
2772026-05-11T04:27:44.985ZMay 11 04:27:44.947 DEBG [sc] cr1 waiting for prompt
2782026-05-11T04:27:44.985ZMay 11 04:27:44.958 DEBG [sc] ox: logging in
2792026-05-11T04:27:44.985ZMay 11 04:27:44.959 DEBG [sc] cr2: logging in
2802026-05-11T04:27:44.985ZMay 11 04:27:44.959 DEBG [sc] cr1: logging in
2812026-05-11T04:27:45.059ZMay 11 04:27:45.046 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
2822026-05-11T04:27:45.104ZMay 11 04:27:45.091 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
2832026-05-11T04:27:45.349ZMay 11 04:27:45.336 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
2842026-05-11T04:27:47.356ZMay 11 04:27:47.343 INFO cr2: executing eos script show version
2852026-05-11T04:27:47.356ZMay 11 04:27:47.343 DEBG [sc] cr2: starting
2862026-05-11T04:27:47.356ZMay 11 04:27:47.343 DEBG [sc] cr2: connecting to [::1]:46204
2872026-05-11T04:27:47.381ZMay 11 04:27:47.343 DEBG [sc] cr2 waiting for prompt
2882026-05-11T04:27:47.381ZMay 11 04:27:47.354 DEBG [sc] cr2: logging in
2892026-05-11T04:27:47.521ZMay 11 04:27:47.508 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
2902026-05-11T04:27:50.535ZMay 11 04:27:50.522 DEBG [sc] ox: starting
2912026-05-11T04:27:50.535ZMay 11 04:27:50.522 DEBG [sc] ox: connecting to [::1]:54791
2922026-05-11T04:27:50.560ZMay 11 04:27:50.523 DEBG [sc] ox waiting for prompt
2932026-05-11T04:27:50.560ZMay 11 04:27:50.533 DEBG [sc] ox: logging in
2942026-05-11T04:27:50.634ZMay 11 04:27:50.621 DEBG [sc] ox: executing command `chmod +x npuvm`
2952026-05-11T04:27:50.701ZMay 11 04:27:50.687 DEBG [sc] ox: starting
2962026-05-11T04:27:50.701ZMay 11 04:27:50.687 DEBG [sc] ox: connecting to [::1]:54791
2972026-05-11T04:27:50.726ZMay 11 04:27:50.688 DEBG [sc] ox waiting for prompt
2982026-05-11T04:27:50.726ZMay 11 04:27:50.698 DEBG [sc] ox: logging in
2992026-05-11T04:27:50.801ZMay 11 04:27:50.787 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
3002026-05-11T04:27:55.668ZMay 11 04:27:55.655 DEBG [sc] cr2: starting
3012026-05-11T04:27:55.668ZMay 11 04:27:55.655 DEBG [sc] cr2: connecting to [::1]:46204
3022026-05-11T04:27:55.693ZMay 11 04:27:55.655 DEBG [sc] cr2 waiting for prompt
3032026-05-11T04:27:55.693ZMay 11 04:27:55.667 DEBG [sc] cr2: logging in
3042026-05-11T04:27:55.813ZMay 11 04:27:55.800 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3052026-05-11T04:27:57.952ZMay 11 04:27:57.939 INFO cr2: executing eos script show version
3062026-05-11T04:27:57.952ZMay 11 04:27:57.939 DEBG [sc] cr2: starting
3072026-05-11T04:27:57.952ZMay 11 04:27:57.939 DEBG [sc] cr2: connecting to [::1]:46204
3082026-05-11T04:27:57.977ZMay 11 04:27:57.940 DEBG [sc] cr2 waiting for prompt
3092026-05-11T04:27:57.977ZMay 11 04:27:57.950 DEBG [sc] cr2: logging in
3102026-05-11T04:27:58.118ZMay 11 04:27:58.105 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3112026-05-11T04:28:00.454ZMay 11 04:28:00.417 DEBG [sc] cr2: starting
3122026-05-11T04:28:00.454ZMay 11 04:28:00.417 DEBG [sc] cr2: connecting to [::1]:46204
3132026-05-11T04:28:00.454ZMay 11 04:28:00.418 DEBG [sc] cr2 waiting for prompt
3142026-05-11T04:28:00.454ZMay 11 04:28:00.428 DEBG [sc] cr2: logging in
3152026-05-11T04:28:00.573ZMay 11 04:28:00.560 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3162026-05-11T04:28:02.703ZMay 11 04:28:02.690 INFO cr2: executing eos script show version
3172026-05-11T04:28:02.703ZMay 11 04:28:02.690 DEBG [sc] cr2: starting
3182026-05-11T04:28:02.703ZMay 11 04:28:02.690 DEBG [sc] cr2: connecting to [::1]:46204
3192026-05-11T04:28:02.728ZMay 11 04:28:02.690 DEBG [sc] cr2 waiting for prompt
3202026-05-11T04:28:02.728ZMay 11 04:28:02.701 DEBG [sc] cr2: logging in
3212026-05-11T04:28:02.868ZMay 11 04:28:02.855 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3222026-05-11T04:28:11.835ZMay 11 04:28:05.333 DEBG [sc] cr2: starting
3232026-05-11T04:28:11.835ZMay 11 04:28:05.333 DEBG [sc] cr2: connecting to [::1]:46204
3242026-05-11T04:28:11.859ZMay 11 04:28:05.333 DEBG [sc] cr2 waiting for prompt
3252026-05-11T04:28:11.859ZMay 11 04:28:05.344 DEBG [sc] cr2: logging in
3262026-05-11T04:28:12.131ZMay 11 04:28:05.488 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3272026-05-11T04:28:12.131ZMay 11 04:28:07.570 INFO cr2: executing eos script show version
3282026-05-11T04:28:12.131ZMay 11 04:28:07.570 DEBG [sc] cr2: starting
3292026-05-11T04:28:12.131ZMay 11 04:28:07.570 DEBG [sc] cr2: connecting to [::1]:46204
3302026-05-11T04:28:12.131ZMay 11 04:28:07.571 DEBG [sc] cr2 waiting for prompt
3312026-05-11T04:28:12.131ZMay 11 04:28:07.581 DEBG [sc] cr2: logging in
3322026-05-11T04:28:12.131ZMay 11 04:28:07.736 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3332026-05-11T04:28:12.131ZMay 11 04:28:10.057 INFO cr2: executing eos script
3342026-05-11T04:28:12.131Z enable
3352026-05-11T04:28:12.131Z configure
3362026-05-11T04:28:12.131Z ipv6 unicast-routing
3372026-05-11T04:28:12.131Z ip routing ipv6 interfaces
3382026-05-11T04:28:12.131Z ip routing
3392026-05-11T04:28:12.131Z ip route 1.2.3.0/24 null0
3402026-05-11T04:28:12.131Z ipv6 route fd99::/64 null0
3412026-05-11T04:28:12.131Z interface et1
3422026-05-11T04:28:12.131Z no switchport
3432026-05-11T04:28:12.131Z ipv6 enable
3442026-05-11T04:28:12.131Z
3452026-05-11T04:28:12.131Z router bgp 45
3462026-05-11T04:28:12.131Z router-id 1.2.3.1
3472026-05-11T04:28:12.131Z no bgp default ipv4-unicast
3482026-05-11T04:28:12.131Z timers bgp 2 6
3492026-05-11T04:28:12.132Z neighbor ebgp peer group
3502026-05-11T04:28:12.132Z neighbor ebgp remote-as 33
3512026-05-11T04:28:12.132Z neighbor interface Et1 peer-group ebgp
3522026-05-11T04:28:12.132Z address-family ipv4
3532026-05-11T04:28:12.132Z neighbor ebgp activate
3542026-05-11T04:28:12.132Z neighbor ebgp next-hop address-family ipv6 originate
3552026-05-11T04:28:12.132Z network 1.2.3.0/24
3562026-05-11T04:28:12.132Z exit
3572026-05-11T04:28:12.132Z address-family ipv6
3582026-05-11T04:28:12.132Z neighbor ebgp activate
3592026-05-11T04:28:12.132Z neighbor ebgp next-hop address-family ipv6 originate
3602026-05-11T04:28:12.132Z network fd99::/64
3612026-05-11T04:28:12.132Z exit
3622026-05-11T04:28:12.132Z exit
3632026-05-11T04:28:12.132Z
3642026-05-11T04:28:12.132ZMay 11 04:28:10.057 DEBG [sc] cr2: starting
3652026-05-11T04:28:12.132ZMay 11 04:28:10.057 DEBG [sc] cr2: connecting to [::1]:46204
3662026-05-11T04:28:12.132ZMay 11 04:28:10.057 DEBG [sc] cr2 waiting for prompt
3672026-05-11T04:28:12.132ZMay 11 04:28:10.068 DEBG [sc] cr2: logging in
3682026-05-11T04:28:12.132ZMay 11 04:28:10.232 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
3692026-05-11T04:28:12.132Z enable
3702026-05-11T04:28:12.132Z configure
3712026-05-11T04:28:12.132Z ipv6 unicast-routing
3722026-05-11T04:28:12.132Z ip routing ipv6 interfaces
3732026-05-11T04:28:12.132Z ip routing
3742026-05-11T04:28:12.132Z ip route 1.2.3.0/24 null0
3752026-05-11T04:28:12.132Z ipv6 route fd99::/64 null0
3762026-05-11T04:28:12.132Z interface et1
3772026-05-11T04:28:12.132Z no switchport
3782026-05-11T04:28:12.132Z ipv6 enable
3792026-05-11T04:28:12.132Z
3802026-05-11T04:28:12.132Z router bgp 45
3812026-05-11T04:28:12.132Z router-id 1.2.3.1
3822026-05-11T04:28:12.132Z no bgp default ipv4-unicast
3832026-05-11T04:28:12.132Z timers bgp 2 6
3842026-05-11T04:28:12.132Z neighbor ebgp peer group
3852026-05-11T04:28:12.132Z neighbor ebgp remote-as 33
3862026-05-11T04:28:12.132Z neighbor interface Et1 peer-group ebgp
3872026-05-11T04:28:12.132Z address-family ipv4
3882026-05-11T04:28:12.133Z neighbor ebgp activate
3892026-05-11T04:28:12.133Z neighbor ebgp next-hop address-family ipv6 originate
3902026-05-11T04:28:12.133Z network 1.2.3.0/24
3912026-05-11T04:28:12.133Z exit
3922026-05-11T04:28:12.133Z address-family ipv6
3932026-05-11T04:28:12.133Z neighbor ebgp activate
3942026-05-11T04:28:12.133Z neighbor ebgp next-hop address-family ipv6 originate
3952026-05-11T04:28:12.133Z network fd99::/64
3962026-05-11T04:28:12.133Z exit
3972026-05-11T04:28:12.133Z exit
3982026-05-11T04:28:12.133Z '`
3992026-05-11T04:28:22.780ZMay 11 04:28:22.767 INFO cr1: enabling frr daemon bgpd
4002026-05-11T04:28:22.780ZMay 11 04:28:22.767 DEBG [sc] cr1: starting
4012026-05-11T04:28:22.780ZMay 11 04:28:22.767 DEBG [sc] cr1: connecting to [::1]:34296
4022026-05-11T04:28:22.804ZMay 11 04:28:22.767 DEBG [sc] cr1 waiting for prompt
4032026-05-11T04:28:22.804ZMay 11 04:28:22.778 DEBG [sc] cr1: logging in
4042026-05-11T04:28:22.925ZMay 11 04:28:22.911 DEBG [sc] cr1: executing command `sed -i 's/bgpd=no/bgpd=yes/g' /etc/frr/daemons`
4052026-05-11T04:28:24.993ZMay 11 04:28:24.979 DEBG [sc] cr1: starting
4062026-05-11T04:28:24.993ZMay 11 04:28:24.979 DEBG [sc] cr1: connecting to [::1]:34296
4072026-05-11T04:28:25.017ZMay 11 04:28:24.980 DEBG [sc] cr1 waiting for prompt
4082026-05-11T04:28:25.017ZMay 11 04:28:24.991 DEBG [sc] cr1: logging in
4092026-05-11T04:28:25.159ZMay 11 04:28:25.145 DEBG [sc] cr1: executing command `systemctl restart frr`
4102026-05-11T04:28:32.800ZMay 11 04:28:32.764 INFO cr1: executing frr script
4112026-05-11T04:28:32.800Z configure
4122026-05-11T04:28:32.800Z ip forwarding
4132026-05-11T04:28:32.800Z ipv6 forwarding
4142026-05-11T04:28:32.800Z ip route 1.2.3.0/24 null0
4152026-05-11T04:28:32.800Z ipv6 route fd99::/64 null0
4162026-05-11T04:28:32.800Z router bgp 44
4172026-05-11T04:28:32.800Z no bgp ebgp-requires-policy
4182026-05-11T04:28:32.800Z timers bgp 2 6
4192026-05-11T04:28:32.800Z neighbor enp0s8 interface remote-as external
4202026-05-11T04:28:32.800Z neighbor enp0s8 timers connect 1
4212026-05-11T04:28:32.800Z address-family ipv4 unicast
4222026-05-11T04:28:32.800Z network 1.2.3.0/24
4232026-05-11T04:28:32.800Z neighbor enp0s8 activate
4242026-05-11T04:28:32.800Z exit-address-family
4252026-05-11T04:28:32.800Z address-family ipv6 unicast
4262026-05-11T04:28:32.800Z network fd99::/64
4272026-05-11T04:28:32.800Z neighbor enp0s8 activate
4282026-05-11T04:28:32.800Z exit-address-family
4292026-05-11T04:28:32.800Z exit
4302026-05-11T04:28:32.800Z
4312026-05-11T04:28:32.800ZMay 11 04:28:32.764 DEBG [sc] cr1: starting
4322026-05-11T04:28:32.800ZMay 11 04:28:32.764 DEBG [sc] cr1: connecting to [::1]:34296
4332026-05-11T04:28:32.825ZMay 11 04:28:32.765 DEBG [sc] cr1 waiting for prompt
4342026-05-11T04:28:32.825ZMay 11 04:28:32.776 DEBG [sc] cr1: logging in
4352026-05-11T04:28:32.934ZMay 11 04:28:32.921 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 ' '`
4362026-05-11T04:29:43.204ZMay 11 04:29:43.190 DEBG [sc] ox: starting
4372026-05-11T04:29:43.204ZMay 11 04:29:43.191 DEBG [sc] ox: connecting to [::1]:54791
4382026-05-11T04:29:43.228ZMay 11 04:29:43.191 DEBG [sc] ox waiting for prompt
4392026-05-11T04:29:43.228ZMay 11 04:29:43.201 DEBG [sc] ox: logging in
4402026-05-11T04:29:43.292ZMay 11 04:29:43.279 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
4412026-05-11T04:29:43.608ZMay 11 04:29:43.595 DEBG [sc] ox: starting
4422026-05-11T04:29:43.608ZMay 11 04:29:43.595 DEBG [sc] ox: connecting to [::1]:54791
4432026-05-11T04:29:43.633ZMay 11 04:29:43.596 DEBG [sc] ox waiting for prompt
4442026-05-11T04:29:43.633ZMay 11 04:29:43.607 DEBG [sc] ox: logging in
4452026-05-11T04:29:43.697ZMay 11 04:29:43.684 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4462026-05-11T04:29:44.721ZMay 11 04:29:44.707 DEBG [sc] ox: starting
4472026-05-11T04:29:44.721ZMay 11 04:29:44.707 DEBG [sc] ox: connecting to [::1]:54791
4482026-05-11T04:29:44.745ZMay 11 04:29:44.708 DEBG [sc] ox waiting for prompt
4492026-05-11T04:29:44.745ZMay 11 04:29:44.708 DEBG [sc] ox: logging in
4502026-05-11T04:29:44.798ZMay 11 04:29:44.785 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4512026-05-11T04:29:44.865ZMay 11 04:29:44.851 DEBG [sc] ox: starting
4522026-05-11T04:29:44.865ZMay 11 04:29:44.851 DEBG [sc] ox: connecting to [::1]:54791
4532026-05-11T04:29:44.889ZMay 11 04:29:44.852 DEBG [sc] ox waiting for prompt
4542026-05-11T04:29:44.889ZMay 11 04:29:44.862 DEBG [sc] ox: logging in
4552026-05-11T04:29:44.952ZMay 11 04:29:44.939 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
4562026-05-11T04:29:45.008ZMay 11 04:29:44.995 DEBG [sc] ox: starting
4572026-05-11T04:29:45.008ZMay 11 04:29:44.995 DEBG [sc] ox: connecting to [::1]:54791
4582026-05-11T04:29:45.032ZMay 11 04:29:44.995 DEBG [sc] ox waiting for prompt
4592026-05-11T04:29:45.033ZMay 11 04:29:45.005 DEBG [sc] ox: logging in
4602026-05-11T04:29:45.096ZMay 11 04:29:45.082 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
4612026-05-11T04:29:45.150ZMay 11 04:29:45.137 DEBG [sc] ox: starting
4622026-05-11T04:29:45.150ZMay 11 04:29:45.137 DEBG [sc] ox: connecting to [::1]:54791
4632026-05-11T04:29:45.175ZMay 11 04:29:45.138 DEBG [sc] ox waiting for prompt
4642026-05-11T04:29:45.175ZMay 11 04:29:45.148 DEBG [sc] ox: logging in
4652026-05-11T04:29:45.238ZMay 11 04:29:45.225 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
4662026-05-11T04:29:45.305ZMay 11 04:29:45.291 DEBG [sc] ox: starting
4672026-05-11T04:29:45.305ZMay 11 04:29:45.291 DEBG [sc] ox: connecting to [::1]:54791
4682026-05-11T04:29:45.329ZMay 11 04:29:45.292 DEBG [sc] ox waiting for prompt
4692026-05-11T04:29:45.329ZMay 11 04:29:45.303 DEBG [sc] ox: logging in
4702026-05-11T04:29:45.392ZMay 11 04:29:45.379 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
4712026-05-11T04:29:45.460ZMay 11 04:29:45.435 DEBG [sc] ox: starting
4722026-05-11T04:29:45.460ZMay 11 04:29:45.435 DEBG [sc] ox: connecting to [::1]:54791
4732026-05-11T04:29:45.460ZMay 11 04:29:45.436 DEBG [sc] ox waiting for prompt
4742026-05-11T04:29:45.460ZMay 11 04:29:45.446 DEBG [sc] ox: logging in
4752026-05-11T04:29:45.537ZMay 11 04:29:45.524 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
4762026-05-11T04:29:45.592ZMay 11 04:29:45.579 DEBG [sc] ox: starting
4772026-05-11T04:29:45.592ZMay 11 04:29:45.579 DEBG [sc] ox: connecting to [::1]:54791
4782026-05-11T04:29:45.616ZMay 11 04:29:45.579 DEBG [sc] ox waiting for prompt
4792026-05-11T04:29:45.616ZMay 11 04:29:45.590 DEBG [sc] ox: logging in
4802026-05-11T04:29:45.680ZMay 11 04:29:45.667 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
4812026-05-11T04:29:45.736ZMay 11 04:29:45.723 DEBG [sc] ox: starting
4822026-05-11T04:29:45.736ZMay 11 04:29:45.723 DEBG [sc] ox: connecting to [::1]:54791
4832026-05-11T04:29:45.760ZMay 11 04:29:45.723 DEBG [sc] ox waiting for prompt
4842026-05-11T04:29:45.760ZMay 11 04:29:45.733 DEBG [sc] ox: logging in
4852026-05-11T04:29:45.823ZMay 11 04:29:45.810 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
4862026-05-11T04:29:45.895ZMay 11 04:29:45.882 INFO adding BGP router to mgd
4872026-05-11T04:29:48.975ZMay 11 04:29:48.962 INFO cr1: executing frr script show ip bgp json
4882026-05-11T04:29:48.975ZMay 11 04:29:48.962 DEBG [sc] cr1: starting
4892026-05-11T04:29:48.975ZMay 11 04:29:48.962 DEBG [sc] cr1: connecting to [::1]:34296
4902026-05-11T04:29:49.000ZMay 11 04:29:48.963 DEBG [sc] cr1 waiting for prompt
4912026-05-11T04:29:49.000ZMay 11 04:29:48.973 DEBG [sc] cr1: logging in
4922026-05-11T04:29:49.323ZMay 11 04:29:49.309 DEBG [sc] cr1: executing command `vtysh -c 'show ip bgp json'`
4932026-05-11T04:29:51.455ZMay 11 04:29:51.441 INFO cr1: executing frr script show bgp json
4942026-05-11T04:29:51.455ZMay 11 04:29:51.441 DEBG [sc] cr1: starting
4952026-05-11T04:29:51.455ZMay 11 04:29:51.441 DEBG [sc] cr1: connecting to [::1]:34296
4962026-05-11T04:29:51.480ZMay 11 04:29:51.442 DEBG [sc] cr1 waiting for prompt
4972026-05-11T04:29:51.480ZMay 11 04:29:51.453 DEBG [sc] cr1: logging in
4982026-05-11T04:29:51.598ZMay 11 04:29:51.584 DEBG [sc] cr1: executing command `vtysh -c 'show bgp json'`
4992026-05-11T04:29:53.737ZMay 11 04:29:53.724 INFO cr2: executing eos script show ip bgp | json
5002026-05-11T04:29:53.737ZMay 11 04:29:53.724 DEBG [sc] cr2: starting
5012026-05-11T04:29:53.737ZMay 11 04:29:53.724 DEBG [sc] cr2: connecting to [::1]:46204
5022026-05-11T04:29:53.762ZMay 11 04:29:53.725 DEBG [sc] cr2 waiting for prompt
5032026-05-11T04:29:53.762ZMay 11 04:29:53.736 DEBG [sc] cr2: logging in
5042026-05-11T04:29:54.124ZMay 11 04:29:54.111 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ip bgp | json'`
5052026-05-11T04:29:56.530ZMay 11 04:29:56.516 INFO cr2: executing eos script show ipv6 bgp | json
5062026-05-11T04:29:56.530ZMay 11 04:29:56.516 DEBG [sc] cr2: starting
5072026-05-11T04:29:56.531ZMay 11 04:29:56.517 DEBG [sc] cr2: connecting to [::1]:46204
5082026-05-11T04:29:56.555ZMay 11 04:29:56.518 DEBG [sc] cr2 waiting for prompt
5092026-05-11T04:29:56.555ZMay 11 04:29:56.527 DEBG [sc] cr2: logging in
5102026-05-11T04:29:56.663ZMay 11 04:29:56.650 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ipv6 bgp | json'`
5112026-05-11T04:29:59.028ZMay 11 04:29:59.014 INFO trio bgp unnumbered test passed 🎉
5122026-05-11T04:29:59.028ZMay 11 04:29:59.014 INFO destroying runner for deployment mgtriou
5132026-05-11T04:29:59.028ZMay 11 04:29:59.014 INFO destroying deployment mgtriou
5142026-05-11T04:29:59.028ZMay 11 04:29:59.014 INFO destroying nodes
5152026-05-11T04:29:59.119ZMay 11 04:29:59.106 INFO destroying links
5162026-05-11T04:29:59.119ZMay 11 04:29:59.106 INFO destroying link mgtriou_ox_sn_vnic0
5172026-05-11T04:29:59.143ZMay 11 04:29:59.108 INFO destroying link mgtriou_ox_sn_sim0
5182026-05-11T04:29:59.143ZMay 11 04:29:59.109 INFO destroying link mgtriou_cr1_vn_vnic0
5192026-05-11T04:30:00.126ZMay 11 04:30:00.113 INFO destroying link mgtriou_cr1_vn_sim0
5202026-05-11T04:30:00.151ZMay 11 04:30:00.114 INFO destroying link mgtriou_ox_sn_vnic1
5212026-05-11T04:30:00.151ZMay 11 04:30:00.115 INFO destroying link mgtriou_ox_sn_sim1
5222026-05-11T04:30:00.151ZMay 11 04:30:00.116 INFO destroying link mgtriou_cr2_vn_vnic0
5232026-05-11T04:30:00.151ZMay 11 04:30:00.117 INFO destroying link mgtriou_cr2_vn_sim0
5242026-05-11T04:30:00.151ZMay 11 04:30:00.119 INFO destroying external links
5252026-05-11T04:30:00.151ZMay 11 04:30:00.119 INFO destroying external link mgtriou_ox_vn_vnic2
5262026-05-11T04:30:00.151ZMay 11 04:30:00.120 INFO destroying external link mgtriou_cr1_vn_vnic1
5272026-05-11T04:30:00.151ZMay 11 04:30:00.121 INFO destroying external link mgtriou_cr2_vn_vnic1
5282026-05-11T04:30:00.151ZMay 11 04:30:00.123 INFO destroying images
5292026-05-11T04:30:00.618ZMay 11 04:30:00.604 INFO destroying workspace at .falcon
5302026-05-11T04:30:00.642Z+ RUST_LOG=debug
5312026-05-11T04:30:00.642Z+ pfexec ./falcon-lab run trio-bfd-static-routing
5322026-05-11T04:30:00.666ZMay 11 04:30:00.645 DEBG using default route interface igb0
5332026-05-11T04:30:00.666ZMay 11 04:30:00.645 DEBG using default route interface igb0
5342026-05-11T04:30:00.666ZMay 11 04:30:00.645 DEBG using default route interface igb0
5352026-05-11T04:30:00.666ZMay 11 04:30:00.645 INFO launching runner: deployment(mgtriobfd) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
5362026-05-11T04:30:00.666ZMay 11 04:30:00.645 INFO starting preflight for deployment mgtriobfd
5372026-05-11T04:30:01.399ZMay 11 04:30:01.386 INFO creating links
5382026-05-11T04:30:01.399ZMay 11 04:30:01.386 DEBG destroying link mgtriobfd_ox_sn_vnic0
5392026-05-11T04:30:01.399ZMay 11 04:30:01.386 DEBG destroying link mgtriobfd_ox_sn_sim0
5402026-05-11T04:30:01.399ZMay 11 04:30:01.386 INFO creating simnet link 'mgtriobfd_ox_sn_sim0'
5412026-05-11T04:30:01.424ZMay 11 04:30:01.388 INFO creating vnic link 'mgtriobfd_ox_sn_vnic0'
5422026-05-11T04:30:01.424ZMay 11 04:30:01.396 DEBG link pair created
5432026-05-11T04:30:01.424ZMay 11 04:30:01.396 DEBG destroying link mgtriobfd_cr1_vn_vnic0
5442026-05-11T04:30:01.424ZMay 11 04:30:01.396 DEBG destroying link mgtriobfd_cr1_vn_sim0
5452026-05-11T04:30:01.424ZMay 11 04:30:01.396 INFO creating simnet link 'mgtriobfd_cr1_vn_sim0'
5462026-05-11T04:30:01.424ZMay 11 04:30:01.397 INFO creating vnic link 'mgtriobfd_cr1_vn_vnic0'
5472026-05-11T04:30:01.424ZMay 11 04:30:01.403 DEBG link pair created
5482026-05-11T04:30:01.424ZMay 11 04:30:01.403 DEBG destroying link mgtriobfd_ox_sn_vnic1
5492026-05-11T04:30:01.424ZMay 11 04:30:01.403 DEBG destroying link mgtriobfd_ox_sn_sim1
5502026-05-11T04:30:01.424ZMay 11 04:30:01.403 INFO creating simnet link 'mgtriobfd_ox_sn_sim1'
5512026-05-11T04:30:01.424ZMay 11 04:30:01.404 INFO creating vnic link 'mgtriobfd_ox_sn_vnic1'
5522026-05-11T04:30:01.424ZMay 11 04:30:01.411 DEBG link pair created
5532026-05-11T04:30:01.424ZMay 11 04:30:01.411 DEBG destroying link mgtriobfd_cr2_vn_vnic0
5542026-05-11T04:30:01.424ZMay 11 04:30:01.411 DEBG destroying link mgtriobfd_cr2_vn_sim0
5552026-05-11T04:30:01.425ZMay 11 04:30:01.411 INFO creating simnet link 'mgtriobfd_cr2_vn_sim0'
5562026-05-11T04:30:01.450ZMay 11 04:30:01.412 INFO creating vnic link 'mgtriobfd_cr2_vn_vnic0'
5572026-05-11T04:30:01.450ZMay 11 04:30:01.418 DEBG link pair created
5582026-05-11T04:30:01.450ZMay 11 04:30:01.418 INFO creating external links
5592026-05-11T04:30:01.450ZMay 11 04:30:01.418 DEBG destroying external link mgtriobfd_ox_vn_vnic2
5602026-05-11T04:30:01.450ZMay 11 04:30:01.418 INFO creating external link mgtriobfd_ox_vn_vnic2
5612026-05-11T04:30:01.450ZMay 11 04:30:01.419 DEBG external link mgtriobfd_ox_vn_vnic2@igb0 created
5622026-05-11T04:30:01.450ZMay 11 04:30:01.419 DEBG destroying external link mgtriobfd_cr1_vn_vnic1
5632026-05-11T04:30:01.450ZMay 11 04:30:01.419 INFO creating external link mgtriobfd_cr1_vn_vnic1
5642026-05-11T04:30:01.450ZMay 11 04:30:01.420 DEBG external link mgtriobfd_cr1_vn_vnic1@igb0 created
5652026-05-11T04:30:01.450ZMay 11 04:30:01.420 DEBG destroying external link mgtriobfd_cr2_vn_vnic1
5662026-05-11T04:30:01.450ZMay 11 04:30:01.420 INFO creating external link mgtriobfd_cr2_vn_vnic1
5672026-05-11T04:30:01.450ZMay 11 04:30:01.421 DEBG external link mgtriobfd_cr2_vn_vnic1@igb0 created
5682026-05-11T04:30:01.450ZMay 11 04:30:01.421 INFO creating nodes
5692026-05-11T04:30:01.450ZMay 11 04:30:01.421 INFO ox: launching node
5702026-05-11T04:30:01.450ZMay 11 04:30:01.424 INFO cr1: launching node
5712026-05-11T04:30:01.450ZMay 11 04:30:01.426 INFO cr2: launching node
5722026-05-11T04:30:01.475ZMay 11 04:30:01.440 INFO launched instance ox with pid 893 on port 49014
5732026-05-11T04:30:01.475ZMay 11 04:30:01.440 INFO ox: instance ensure
5742026-05-11T04:30:01.475ZMay 11 04:30:01.440 INFO launched instance cr1 with pid 894 on port 35206
5752026-05-11T04:30:01.475ZMay 11 04:30:01.440 INFO cr1: instance ensure
5762026-05-11T04:30:01.475ZMay 11 04:30:01.441 INFO launched instance cr2 with pid 895 on port 62803
5772026-05-11T04:30:01.475ZMay 11 04:30:01.441 INFO cr2: instance ensure
5782026-05-11T04:30:03.736ZMay 11 04:30:03.722 INFO cr1: instance run
5792026-05-11T04:30:03.760ZMay 11 04:30:03.723 DEBG [sc] cr1: starting
5802026-05-11T04:30:03.760ZMay 11 04:30:03.723 DEBG [sc] cr1: connecting to [::1]:35206
5812026-05-11T04:30:03.760ZMay 11 04:30:03.724 DEBG [sc] cr1 waiting for prompt
5822026-05-11T04:30:03.785ZMay 11 04:30:03.759 INFO cr2: instance run
5832026-05-11T04:30:03.785ZMay 11 04:30:03.760 DEBG [sc] cr2: starting
5842026-05-11T04:30:03.785ZMay 11 04:30:03.760 DEBG [sc] cr2: connecting to [::1]:62803
5852026-05-11T04:30:03.785ZMay 11 04:30:03.760 DEBG [sc] cr2 waiting for prompt
5862026-05-11T04:30:03.785ZMay 11 04:30:03.761 INFO ox: instance run
5872026-05-11T04:30:03.785ZMay 11 04:30:03.762 DEBG [sc] ox: starting
5882026-05-11T04:30:03.785ZMay 11 04:30:03.762 DEBG [sc] ox: connecting to [::1]:49014
5892026-05-11T04:30:03.785ZMay 11 04:30:03.762 DEBG [sc] ox waiting for prompt
5902026-05-11T04:30:20.833ZMay 11 04:30:20.820 DEBG [sc] cr1: logging in
5912026-05-11T04:30:21.210ZMay 11 04:30:21.197 INFO cr1: mounting /opt/cargo-bay
5922026-05-11T04:30:21.210ZMay 11 04:30:21.197 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5932026-05-11T04:30:21.235ZMay 11 04:30:21.219 DEBG [sc] cr1: executing command `cd`
5942026-05-11T04:30:21.259ZMay 11 04:30:21.230 INFO cr1: finished mounting /opt/cargo-bay
5952026-05-11T04:30:21.259ZMay 11 04:30:21.230 DEBG [sc] cr1: executing command `hostname cr1`
5962026-05-11T04:30:21.259ZMay 11 04:30:21.241 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
5972026-05-11T04:30:21.283ZMay 11 04:30:21.252 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
5982026-05-11T04:30:21.283ZMay 11 04:30:21.264 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
5992026-05-11T04:30:21.307ZMay 11 04:30:21.275 INFO cr1: logging out
6002026-05-11T04:30:23.369ZMay 11 04:30:23.355 INFO cr1: logged out
6012026-05-11T04:30:24.160ZMay 11 04:30:24.146 DEBG [sc] ox: logging in
6022026-05-11T04:30:24.333ZMay 11 04:30:24.311 INFO ox: mounting /opt/cargo-bay
6032026-05-11T04:30:24.333ZMay 11 04:30:24.311 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
6042026-05-11T04:30:25.415ZMay 11 04:30:25.402 DEBG [sc] ox: executing command `cd`
6052026-05-11T04:30:25.465ZMay 11 04:30:25.413 INFO ox: finished mounting /opt/cargo-bay
6062026-05-11T04:30:25.465ZMay 11 04:30:25.413 DEBG [sc] ox: executing command `hostname ox`
6072026-05-11T04:30:25.489ZMay 11 04:30:25.424 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
6082026-05-11T04:30:25.489ZMay 11 04:30:25.435 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
6092026-05-11T04:30:25.489ZMay 11 04:30:25.445 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
6102026-05-11T04:30:25.489ZMay 11 04:30:25.456 INFO ox: logging out
6112026-05-11T04:30:25.489ZMay 11 04:30:25.459 DEBG [sc] cr2: logging in
6122026-05-11T04:30:25.536ZMay 11 04:30:25.523 INFO ox: logged out
6132026-05-11T04:30:25.852ZMay 11 04:30:25.839 INFO cr2: mounting /opt/cargo-bay
6142026-05-11T04:30:25.852ZMay 11 04:30:25.839 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
6152026-05-11T04:30:25.876ZMay 11 04:30:25.861 DEBG [sc] cr2: executing command `cd`
6162026-05-11T04:30:25.900ZMay 11 04:30:25.872 INFO cr2: finished mounting /opt/cargo-bay
6172026-05-11T04:30:25.900ZMay 11 04:30:25.872 DEBG [sc] cr2: executing command `hostname cr2`
6182026-05-11T04:30:25.900ZMay 11 04:30:25.884 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
6192026-05-11T04:30:25.924ZMay 11 04:30:25.895 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
6202026-05-11T04:30:25.924ZMay 11 04:30:25.906 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
6212026-05-11T04:30:25.948ZMay 11 04:30:25.916 INFO cr2: logging out
6222026-05-11T04:30:28.896ZMay 11 04:30:28.883 INFO cr2: logged out
6232026-05-11T04:30:28.920ZMay 11 04:30:28.883 DEBG [sc] ox: starting
6242026-05-11T04:30:28.921ZMay 11 04:30:28.883 DEBG [sc] ox: connecting to [::1]:49014
6252026-05-11T04:30:28.921ZMay 11 04:30:28.884 DEBG [sc] ox waiting for prompt
6262026-05-11T04:30:28.921ZMay 11 04:30:28.895 DEBG [sc] ox: logging in
6272026-05-11T04:30:28.996ZMay 11 04:30:28.983 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
6282026-05-11T04:30:33.946ZMay 11 04:30:33.932 DEBG [sc] ox: starting
6292026-05-11T04:30:33.946ZMay 11 04:30:33.932 DEBG [sc] ox: connecting to [::1]:49014
6302026-05-11T04:30:33.970ZMay 11 04:30:33.933 DEBG [sc] ox waiting for prompt
6312026-05-11T04:30:33.970ZMay 11 04:30:33.943 DEBG [sc] ox: logging in
6322026-05-11T04:30:34.034ZMay 11 04:30:34.021 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
6332026-05-11T04:30:34.110ZMay 11 04:30:34.097 DEBG [sc] ox: starting
6342026-05-11T04:30:34.110ZMay 11 04:30:34.097 DEBG [sc] ox: connecting to [::1]:49014
6352026-05-11T04:30:34.135ZMay 11 04:30:34.097 DEBG [sc] ox waiting for prompt
6362026-05-11T04:30:34.135ZMay 11 04:30:34.109 DEBG [sc] ox: logging in
6372026-05-11T04:30:34.210ZMay 11 04:30:34.196 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
6382026-05-11T04:30:34.275ZMay 11 04:30:34.262 INFO cr1: installing frr
6392026-05-11T04:30:34.275ZMay 11 04:30:34.262 INFO ox: setting up npuvm
6402026-05-11T04:30:34.275ZMay 11 04:30:34.262 INFO waiting for ceos to initialize
6412026-05-11T04:30:34.300ZMay 11 04:30:34.262 DEBG [sc] cr2: starting
6422026-05-11T04:30:34.300ZMay 11 04:30:34.262 DEBG [sc] cr2: connecting to [::1]:62803
6432026-05-11T04:30:34.300ZMay 11 04:30:34.262 DEBG [sc] cr1: starting
6442026-05-11T04:30:34.300ZMay 11 04:30:34.262 DEBG [sc] cr1: connecting to [::1]:35206
6452026-05-11T04:30:34.300ZMay 11 04:30:34.262 DEBG [sc] ox: starting
6462026-05-11T04:30:34.300ZMay 11 04:30:34.262 DEBG [sc] ox: connecting to [::1]:49014
6472026-05-11T04:30:34.300ZMay 11 04:30:34.263 DEBG [sc] ox waiting for prompt
6482026-05-11T04:30:34.300ZMay 11 04:30:34.263 DEBG [sc] cr2 waiting for prompt
6492026-05-11T04:30:34.300ZMay 11 04:30:34.263 DEBG [sc] cr1 waiting for prompt
6502026-05-11T04:30:34.300ZMay 11 04:30:34.273 DEBG [sc] ox: logging in
6512026-05-11T04:30:34.300ZMay 11 04:30:34.274 DEBG [sc] cr2: logging in
6522026-05-11T04:30:34.300ZMay 11 04:30:34.274 DEBG [sc] cr1: logging in
6532026-05-11T04:30:34.363ZMay 11 04:30:34.350 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
6542026-05-11T04:30:34.431ZMay 11 04:30:34.417 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6552026-05-11T04:30:34.697ZMay 11 04:30:34.684 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
6562026-05-11T04:30:36.728ZMay 11 04:30:36.714 INFO cr2: executing eos script show version
6572026-05-11T04:30:36.752ZMay 11 04:30:36.715 DEBG [sc] cr2: starting
6582026-05-11T04:30:36.752ZMay 11 04:30:36.715 DEBG [sc] cr2: connecting to [::1]:62803
6592026-05-11T04:30:36.752ZMay 11 04:30:36.715 DEBG [sc] cr2 waiting for prompt
6602026-05-11T04:30:36.752ZMay 11 04:30:36.725 DEBG [sc] cr2: logging in
6612026-05-11T04:30:36.893ZMay 11 04:30:36.879 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6622026-05-11T04:30:40.242ZMay 11 04:30:40.228 DEBG [sc] ox: starting
6632026-05-11T04:30:40.242ZMay 11 04:30:40.228 DEBG [sc] ox: connecting to [::1]:49014
6642026-05-11T04:30:40.266ZMay 11 04:30:40.229 DEBG [sc] ox waiting for prompt
6652026-05-11T04:30:40.266ZMay 11 04:30:40.239 DEBG [sc] ox: logging in
6662026-05-11T04:30:40.331ZMay 11 04:30:40.316 DEBG [sc] ox: executing command `chmod +x npuvm`
6672026-05-11T04:30:40.396ZMay 11 04:30:40.383 DEBG [sc] ox: starting
6682026-05-11T04:30:40.396ZMay 11 04:30:40.383 DEBG [sc] ox: connecting to [::1]:49014
6692026-05-11T04:30:40.420ZMay 11 04:30:40.383 DEBG [sc] ox waiting for prompt
6702026-05-11T04:30:40.420ZMay 11 04:30:40.393 DEBG [sc] ox: logging in
6712026-05-11T04:30:40.484ZMay 11 04:30:40.470 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
6722026-05-11T04:30:46.260ZMay 11 04:30:46.246 DEBG [sc] cr2: starting
6732026-05-11T04:30:46.260ZMay 11 04:30:46.246 DEBG [sc] cr2: connecting to [::1]:62803
6742026-05-11T04:30:46.284ZMay 11 04:30:46.247 DEBG [sc] cr2 waiting for prompt
6752026-05-11T04:30:46.284ZMay 11 04:30:46.257 DEBG [sc] cr2: logging in
6762026-05-11T04:30:46.402ZMay 11 04:30:46.389 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6772026-05-11T04:30:48.517ZMay 11 04:30:48.503 INFO cr2: executing eos script show version
6782026-05-11T04:30:48.517ZMay 11 04:30:48.503 DEBG [sc] cr2: starting
6792026-05-11T04:30:48.517ZMay 11 04:30:48.503 DEBG [sc] cr2: connecting to [::1]:62803
6802026-05-11T04:30:48.542ZMay 11 04:30:48.504 DEBG [sc] cr2 waiting for prompt
6812026-05-11T04:30:48.542ZMay 11 04:30:48.514 DEBG [sc] cr2: logging in
6822026-05-11T04:30:48.694ZMay 11 04:30:48.680 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6832026-05-11T04:30:51.078ZMay 11 04:30:51.065 DEBG [sc] cr2: starting
6842026-05-11T04:30:51.078ZMay 11 04:30:51.065 DEBG [sc] cr2: connecting to [::1]:62803
6852026-05-11T04:30:51.102ZMay 11 04:30:51.065 DEBG [sc] cr2 waiting for prompt
6862026-05-11T04:30:51.102ZMay 11 04:30:51.076 DEBG [sc] cr2: logging in
6872026-05-11T04:30:51.254ZMay 11 04:30:51.241 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6882026-05-11T04:30:53.408ZMay 11 04:30:53.395 INFO cr2: executing eos script show version
6892026-05-11T04:30:53.408ZMay 11 04:30:53.395 DEBG [sc] cr2: starting
6902026-05-11T04:30:53.432ZMay 11 04:30:53.395 DEBG [sc] cr2: connecting to [::1]:62803
6912026-05-11T04:30:53.432ZMay 11 04:30:53.396 DEBG [sc] cr2 waiting for prompt
6922026-05-11T04:30:53.432ZMay 11 04:30:53.406 DEBG [sc] cr2: logging in
6932026-05-11T04:30:53.585ZMay 11 04:30:53.572 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6942026-05-11T04:30:56.032ZMay 11 04:30:56.019 INFO cr2: executing eos script
6952026-05-11T04:30:56.032Z enable
6962026-05-11T04:30:56.033Z configure
6972026-05-11T04:30:56.033Z ip routing
6982026-05-11T04:30:56.033Z ipv6 unicast-routing
6992026-05-11T04:30:56.033Z interface Ethernet1
7002026-05-11T04:30:56.033Z no switchport
7012026-05-11T04:30:56.033Z ip address 10.0.1.2/24
7022026-05-11T04:30:56.033Z ipv6 enable
7032026-05-11T04:30:56.033Z ipv6 address fd00:2::2/64
7042026-05-11T04:30:56.033Z bfd interval 300 min-rx 300 multiplier 3
7052026-05-11T04:30:56.033Z exit
7062026-05-11T04:30:56.033Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7072026-05-11T04:30:56.033Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7082026-05-11T04:30:56.033Z exit
7092026-05-11T04:30:56.033Z
7102026-05-11T04:30:56.033ZMay 11 04:30:56.019 DEBG [sc] cr2: starting
7112026-05-11T04:30:56.033ZMay 11 04:30:56.019 DEBG [sc] cr2: connecting to [::1]:62803
7122026-05-11T04:30:56.057ZMay 11 04:30:56.019 DEBG [sc] cr2 waiting for prompt
7132026-05-11T04:30:56.057ZMay 11 04:30:56.030 DEBG [sc] cr2: logging in
7142026-05-11T04:30:56.198ZMay 11 04:30:56.184 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
7152026-05-11T04:30:56.198Z enable
7162026-05-11T04:30:56.198Z configure
7172026-05-11T04:30:56.198Z ip routing
7182026-05-11T04:30:56.198Z ipv6 unicast-routing
7192026-05-11T04:30:56.198Z interface Ethernet1
7202026-05-11T04:30:56.198Z no switchport
7212026-05-11T04:30:56.198Z ip address 10.0.1.2/24
7222026-05-11T04:30:56.198Z ipv6 enable
7232026-05-11T04:30:56.198Z ipv6 address fd00:2::2/64
7242026-05-11T04:30:56.198Z bfd interval 300 min-rx 300 multiplier 3
7252026-05-11T04:30:56.198Z exit
7262026-05-11T04:30:56.198Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7272026-05-11T04:30:56.198Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7282026-05-11T04:30:56.198Z exit
7292026-05-11T04:30:56.198Z '`
7302026-05-11T04:31:12.150ZMay 11 04:31:12.136 INFO cr1: enabling frr daemon bfdd
7312026-05-11T04:31:12.150ZMay 11 04:31:12.136 DEBG [sc] cr1: starting
7322026-05-11T04:31:12.150ZMay 11 04:31:12.136 DEBG [sc] cr1: connecting to [::1]:35206
7332026-05-11T04:31:12.174ZMay 11 04:31:12.137 DEBG [sc] cr1 waiting for prompt
7342026-05-11T04:31:12.174ZMay 11 04:31:12.147 DEBG [sc] cr1: logging in
7352026-05-11T04:31:12.314ZMay 11 04:31:12.301 DEBG [sc] cr1: executing command `sed -i 's/bfdd=no/bfdd=yes/g' /etc/frr/daemons`
7362026-05-11T04:31:14.393ZMay 11 04:31:14.379 DEBG [sc] cr1: starting
7372026-05-11T04:31:14.393ZMay 11 04:31:14.379 DEBG [sc] cr1: connecting to [::1]:35206
7382026-05-11T04:31:14.417ZMay 11 04:31:14.380 DEBG [sc] cr1 waiting for prompt
7392026-05-11T04:31:14.417ZMay 11 04:31:14.390 DEBG [sc] cr1: logging in
7402026-05-11T04:31:14.547ZMay 11 04:31:14.534 DEBG [sc] cr1: executing command `systemctl restart frr`
7412026-05-11T04:31:22.184ZMay 11 04:31:22.170 INFO cr1: executing frr script
7422026-05-11T04:31:22.184Z configure
7432026-05-11T04:31:22.184Z interface enp0s8
7442026-05-11T04:31:22.184Z ip address 10.0.0.2/24
7452026-05-11T04:31:22.184Z ipv6 address fd00:1::2/64
7462026-05-11T04:31:22.184Z no shutdown
7472026-05-11T04:31:22.184Z exit
7482026-05-11T04:31:22.184Z bfd
7492026-05-11T04:31:22.184Z peer 10.0.0.1 local-address 10.0.0.2
7502026-05-11T04:31:22.184Z detect-multiplier 3
7512026-05-11T04:31:22.184Z receive-interval 300
7522026-05-11T04:31:22.184Z transmit-interval 300
7532026-05-11T04:31:22.184Z no shutdown
7542026-05-11T04:31:22.184Z exit
7552026-05-11T04:31:22.184Z peer fd00:1::1 local-address fd00:1::2
7562026-05-11T04:31:22.184Z detect-multiplier 3
7572026-05-11T04:31:22.184Z receive-interval 300
7582026-05-11T04:31:22.184Z transmit-interval 300
7592026-05-11T04:31:22.184Z no shutdown
7602026-05-11T04:31:22.184Z exit
7612026-05-11T04:31:22.184Z exit
7622026-05-11T04:31:22.184Z
7632026-05-11T04:31:22.184ZMay 11 04:31:22.170 DEBG [sc] cr1: starting
7642026-05-11T04:31:22.184ZMay 11 04:31:22.170 DEBG [sc] cr1: connecting to [::1]:35206
7652026-05-11T04:31:22.209ZMay 11 04:31:22.171 DEBG [sc] cr1 waiting for prompt
7662026-05-11T04:31:22.209ZMay 11 04:31:22.182 DEBG [sc] cr1: logging in
7672026-05-11T04:31:22.339ZMay 11 04:31:22.326 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 ' '`
7682026-05-11T04:32:29.060ZMay 11 04:32:29.046 DEBG [sc] ox: starting
7692026-05-11T04:32:29.060ZMay 11 04:32:29.046 DEBG [sc] ox: connecting to [::1]:49014
7702026-05-11T04:32:29.084ZMay 11 04:32:29.047 DEBG [sc] ox waiting for prompt
7712026-05-11T04:32:29.084ZMay 11 04:32:29.057 DEBG [sc] ox: logging in
7722026-05-11T04:32:29.149ZMay 11 04:32:29.135 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
7732026-05-11T04:32:29.453ZMay 11 04:32:29.440 DEBG [sc] ox: starting
7742026-05-11T04:32:29.453ZMay 11 04:32:29.440 DEBG [sc] ox: connecting to [::1]:49014
7752026-05-11T04:32:29.477ZMay 11 04:32:29.441 DEBG [sc] ox waiting for prompt
7762026-05-11T04:32:29.477ZMay 11 04:32:29.452 DEBG [sc] ox: logging in
7772026-05-11T04:32:29.544ZMay 11 04:32:29.531 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7782026-05-11T04:32:29.599ZMay 11 04:32:29.586 DEBG [sc] ox: starting
7792026-05-11T04:32:29.599ZMay 11 04:32:29.586 DEBG [sc] ox: connecting to [::1]:49014
7802026-05-11T04:32:29.623ZMay 11 04:32:29.586 DEBG [sc] ox waiting for prompt
7812026-05-11T04:32:29.623ZMay 11 04:32:29.597 DEBG [sc] ox: logging in
7822026-05-11T04:32:29.686ZMay 11 04:32:29.673 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7832026-05-11T04:32:30.711ZMay 11 04:32:30.697 DEBG [sc] ox: starting
7842026-05-11T04:32:30.711ZMay 11 04:32:30.697 DEBG [sc] ox: connecting to [::1]:49014
7852026-05-11T04:32:30.735ZMay 11 04:32:30.698 DEBG [sc] ox waiting for prompt
7862026-05-11T04:32:30.735ZMay 11 04:32:30.698 DEBG [sc] ox: logging in
7872026-05-11T04:32:30.789ZMay 11 04:32:30.776 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7882026-05-11T04:32:31.178ZMay 11 04:32:31.165 DEBG [sc] ox: starting
7892026-05-11T04:32:31.178ZMay 11 04:32:31.165 DEBG [sc] ox: connecting to [::1]:49014
7902026-05-11T04:32:31.202ZMay 11 04:32:31.165 DEBG [sc] ox waiting for prompt
7912026-05-11T04:32:31.202ZMay 11 04:32:31.177 DEBG [sc] ox: logging in
7922026-05-11T04:32:31.266ZMay 11 04:32:31.253 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
7932026-05-11T04:32:31.323ZMay 11 04:32:31.309 DEBG [sc] ox: starting
7942026-05-11T04:32:31.323ZMay 11 04:32:31.309 DEBG [sc] ox: connecting to [::1]:49014
7952026-05-11T04:32:31.347ZMay 11 04:32:31.310 DEBG [sc] ox waiting for prompt
7962026-05-11T04:32:31.347ZMay 11 04:32:31.320 DEBG [sc] ox: logging in
7972026-05-11T04:32:31.411ZMay 11 04:32:31.398 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
7982026-05-11T04:32:31.476ZMay 11 04:32:31.463 DEBG [sc] ox: starting
7992026-05-11T04:32:31.476ZMay 11 04:32:31.463 DEBG [sc] ox: connecting to [::1]:49014
8002026-05-11T04:32:31.500ZMay 11 04:32:31.464 DEBG [sc] ox waiting for prompt
8012026-05-11T04:32:31.500ZMay 11 04:32:31.474 DEBG [sc] ox: logging in
8022026-05-11T04:32:31.565ZMay 11 04:32:31.552 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.0.1/24 tfportqsfp0_0/v4`
8032026-05-11T04:32:32.188ZMay 11 04:32:32.174 DEBG [sc] ox: starting
8042026-05-11T04:32:32.188ZMay 11 04:32:32.174 DEBG [sc] ox: connecting to [::1]:49014
8052026-05-11T04:32:32.212ZMay 11 04:32:32.175 DEBG [sc] ox waiting for prompt
8062026-05-11T04:32:32.212ZMay 11 04:32:32.185 DEBG [sc] ox: logging in
8072026-05-11T04:32:32.276ZMay 11 04:32:32.262 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v4 -p -o addr`
8082026-05-11T04:32:32.342ZMay 11 04:32:32.329 DEBG [sc] ox: starting
8092026-05-11T04:32:32.342ZMay 11 04:32:32.329 DEBG [sc] ox: connecting to [::1]:49014
8102026-05-11T04:32:32.366ZMay 11 04:32:32.329 DEBG [sc] ox waiting for prompt
8112026-05-11T04:32:32.366ZMay 11 04:32:32.340 DEBG [sc] ox: logging in
8122026-05-11T04:32:32.431ZMay 11 04:32:32.417 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:1::1/64 tfportqsfp0_0/v6`
8132026-05-11T04:32:32.943ZMay 11 04:32:32.929 DEBG [sc] ox: starting
8142026-05-11T04:32:32.943ZMay 11 04:32:32.929 DEBG [sc] ox: connecting to [::1]:49014
8152026-05-11T04:32:32.967ZMay 11 04:32:32.930 DEBG [sc] ox waiting for prompt
8162026-05-11T04:32:32.967ZMay 11 04:32:32.940 DEBG [sc] ox: logging in
8172026-05-11T04:32:33.032ZMay 11 04:32:33.018 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v6 -p -o addr`
8182026-05-11T04:32:33.087ZMay 11 04:32:33.074 DEBG [sc] ox: starting
8192026-05-11T04:32:33.087ZMay 11 04:32:33.074 DEBG [sc] ox: connecting to [::1]:49014
8202026-05-11T04:32:33.112ZMay 11 04:32:33.075 DEBG [sc] ox waiting for prompt
8212026-05-11T04:32:33.112ZMay 11 04:32:33.086 DEBG [sc] ox: logging in
8222026-05-11T04:32:33.176ZMay 11 04:32:33.162 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
8232026-05-11T04:32:33.232ZMay 11 04:32:33.218 DEBG [sc] ox: starting
8242026-05-11T04:32:33.232ZMay 11 04:32:33.218 DEBG [sc] ox: connecting to [::1]:49014
8252026-05-11T04:32:33.256ZMay 11 04:32:33.219 DEBG [sc] ox waiting for prompt
8262026-05-11T04:32:33.256ZMay 11 04:32:33.230 DEBG [sc] ox: logging in
8272026-05-11T04:32:33.320ZMay 11 04:32:33.306 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
8282026-05-11T04:32:33.376ZMay 11 04:32:33.362 DEBG [sc] ox: starting
8292026-05-11T04:32:33.376ZMay 11 04:32:33.362 DEBG [sc] ox: connecting to [::1]:49014
8302026-05-11T04:32:33.400ZMay 11 04:32:33.363 DEBG [sc] ox waiting for prompt
8312026-05-11T04:32:33.400ZMay 11 04:32:33.372 DEBG [sc] ox: logging in
8322026-05-11T04:32:33.463ZMay 11 04:32:33.449 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.1.1/24 tfportqsfp1_0/v4`
8332026-05-11T04:32:34.041ZMay 11 04:32:34.027 DEBG [sc] ox: starting
8342026-05-11T04:32:34.041ZMay 11 04:32:34.027 DEBG [sc] ox: connecting to [::1]:49014
8352026-05-11T04:32:34.065ZMay 11 04:32:34.028 DEBG [sc] ox waiting for prompt
8362026-05-11T04:32:34.065ZMay 11 04:32:34.038 DEBG [sc] ox: logging in
8372026-05-11T04:32:34.129ZMay 11 04:32:34.115 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v4 -p -o addr`
8382026-05-11T04:32:34.183ZMay 11 04:32:34.170 DEBG [sc] ox: starting
8392026-05-11T04:32:34.183ZMay 11 04:32:34.170 DEBG [sc] ox: connecting to [::1]:49014
8402026-05-11T04:32:34.208ZMay 11 04:32:34.171 DEBG [sc] ox waiting for prompt
8412026-05-11T04:32:34.208ZMay 11 04:32:34.182 DEBG [sc] ox: logging in
8422026-05-11T04:32:34.273ZMay 11 04:32:34.259 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:2::1/64 tfportqsfp1_0/v6`
8432026-05-11T04:32:34.519ZMay 11 04:32:34.506 DEBG [sc] ox: starting
8442026-05-11T04:32:34.519ZMay 11 04:32:34.506 DEBG [sc] ox: connecting to [::1]:49014
8452026-05-11T04:32:34.544ZMay 11 04:32:34.507 DEBG [sc] ox waiting for prompt
8462026-05-11T04:32:34.544ZMay 11 04:32:34.517 DEBG [sc] ox: logging in
8472026-05-11T04:32:34.607ZMay 11 04:32:34.593 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v6 -p -o addr`
8482026-05-11T04:32:34.663ZMay 11 04:32:34.649 DEBG [sc] ox: starting
8492026-05-11T04:32:34.663ZMay 11 04:32:34.649 DEBG [sc] ox: connecting to [::1]:49014
8502026-05-11T04:32:34.687ZMay 11 04:32:34.650 DEBG [sc] ox waiting for prompt
8512026-05-11T04:32:34.687ZMay 11 04:32:34.660 DEBG [sc] ox: logging in
8522026-05-11T04:32:34.751ZMay 11 04:32:34.738 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
8532026-05-11T04:32:34.806ZMay 11 04:32:34.793 DEBG [sc] ox: starting
8542026-05-11T04:32:34.806ZMay 11 04:32:34.793 DEBG [sc] ox: connecting to [::1]:49014
8552026-05-11T04:32:34.830ZMay 11 04:32:34.793 DEBG [sc] ox waiting for prompt
8562026-05-11T04:32:34.830ZMay 11 04:32:34.804 DEBG [sc] ox: logging in
8572026-05-11T04:32:34.895ZMay 11 04:32:34.881 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
8582026-05-11T04:32:34.965ZMay 11 04:32:34.952 INFO installing static v4 route 192.168.100.0/24
8592026-05-11T04:32:34.989ZMay 11 04:32:34.953 INFO installing static v6 route fd01::/64
8602026-05-11T04:32:34.989ZMay 11 04:32:34.953 INFO adding BFD peers for cr1 and cr2 (dual-stack)
8612026-05-11T04:32:34.989ZMay 11 04:32:34.957 INFO phase 1: both peers up
8622026-05-11T04:32:35.973ZMay 11 04:32:35.960 INFO cr1: executing frr script show bfd peers json
8632026-05-11T04:32:35.973ZMay 11 04:32:35.960 DEBG [sc] cr1: starting
8642026-05-11T04:32:35.973ZMay 11 04:32:35.960 DEBG [sc] cr1: connecting to [::1]:35206
8652026-05-11T04:32:35.998ZMay 11 04:32:35.961 DEBG [sc] cr1 waiting for prompt
8662026-05-11T04:32:35.998ZMay 11 04:32:35.972 DEBG [sc] cr1: logging in
8672026-05-11T04:32:36.299ZMay 11 04:32:36.286 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8682026-05-11T04:32:38.453ZMay 11 04:32:38.440 INFO cr1: executing frr script show bfd peers json
8692026-05-11T04:32:38.477ZMay 11 04:32:38.440 DEBG [sc] cr1: starting
8702026-05-11T04:32:38.477ZMay 11 04:32:38.440 DEBG [sc] cr1: connecting to [::1]:35206
8712026-05-11T04:32:38.477ZMay 11 04:32:38.441 DEBG [sc] cr1 waiting for prompt
8722026-05-11T04:32:38.477ZMay 11 04:32:38.450 DEBG [sc] cr1: logging in
8732026-05-11T04:32:38.596ZMay 11 04:32:38.582 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8742026-05-11T04:32:40.728ZMay 11 04:32:40.714 INFO cr2: executing eos script show bfd peers | json
8752026-05-11T04:32:40.728ZMay 11 04:32:40.715 DEBG [sc] cr2: starting
8762026-05-11T04:32:40.728ZMay 11 04:32:40.715 DEBG [sc] cr2: connecting to [::1]:62803
8772026-05-11T04:32:40.752ZMay 11 04:32:40.715 DEBG [sc] cr2 waiting for prompt
8782026-05-11T04:32:40.752ZMay 11 04:32:40.727 DEBG [sc] cr2: logging in
8792026-05-11T04:32:41.103ZMay 11 04:32:41.089 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8802026-05-11T04:32:43.453ZMay 11 04:32:43.439 INFO cr2: executing eos script show bfd peers | json
8812026-05-11T04:32:43.453ZMay 11 04:32:43.439 DEBG [sc] cr2: starting
8822026-05-11T04:32:43.453ZMay 11 04:32:43.439 DEBG [sc] cr2: connecting to [::1]:62803
8832026-05-11T04:32:43.477ZMay 11 04:32:43.440 DEBG [sc] cr2 waiting for prompt
8842026-05-11T04:32:43.477ZMay 11 04:32:43.449 DEBG [sc] cr2: logging in
8852026-05-11T04:32:43.583ZMay 11 04:32:43.570 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8862026-05-11T04:32:45.973ZMay 11 04:32:45.959 INFO phase 2: pause bfdd on cr1
8872026-05-11T04:32:45.973ZMay 11 04:32:45.959 INFO cr1: pausing frr bfdd
8882026-05-11T04:32:45.973ZMay 11 04:32:45.959 DEBG [sc] cr1: starting
8892026-05-11T04:32:45.973ZMay 11 04:32:45.959 DEBG [sc] cr1: connecting to [::1]:35206
8902026-05-11T04:32:45.997ZMay 11 04:32:45.960 DEBG [sc] cr1 waiting for prompt
8912026-05-11T04:32:45.997ZMay 11 04:32:45.970 DEBG [sc] cr1: logging in
8922026-05-11T04:32:46.128ZMay 11 04:32:46.114 DEBG [sc] cr1: executing command `pkill -STOP bfdd`
8932026-05-11T04:32:48.212ZMay 11 04:32:48.199 INFO cr2: executing eos script show bfd peers | json
8942026-05-11T04:32:48.212ZMay 11 04:32:48.199 DEBG [sc] cr2: starting
8952026-05-11T04:32:48.212ZMay 11 04:32:48.199 DEBG [sc] cr2: connecting to [::1]:62803
8962026-05-11T04:32:48.236ZMay 11 04:32:48.199 DEBG [sc] cr2 waiting for prompt
8972026-05-11T04:32:48.237ZMay 11 04:32:48.209 DEBG [sc] cr2: logging in
8982026-05-11T04:32:48.366ZMay 11 04:32:48.352 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8992026-05-11T04:32:50.719ZMay 11 04:32:50.705 INFO cr2: executing eos script show bfd peers | json
9002026-05-11T04:32:50.743ZMay 11 04:32:50.705 DEBG [sc] cr2: starting
9012026-05-11T04:32:50.743ZMay 11 04:32:50.705 DEBG [sc] cr2: connecting to [::1]:62803
9022026-05-11T04:32:50.743ZMay 11 04:32:50.706 DEBG [sc] cr2 waiting for prompt
9032026-05-11T04:32:50.743ZMay 11 04:32:50.716 DEBG [sc] cr2: logging in
9042026-05-11T04:32:50.883ZMay 11 04:32:50.870 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9052026-05-11T04:32:53.209ZMay 11 04:32:53.196 INFO phase 3: pause ceos on cr2
9062026-05-11T04:32:53.209ZMay 11 04:32:53.196 INFO cr2: pausing ceos
9072026-05-11T04:32:53.209ZMay 11 04:32:53.196 DEBG [sc] cr2: starting
9082026-05-11T04:32:53.209ZMay 11 04:32:53.196 DEBG [sc] cr2: connecting to [::1]:62803
9092026-05-11T04:32:53.234ZMay 11 04:32:53.197 DEBG [sc] cr2 waiting for prompt
9102026-05-11T04:32:53.234ZMay 11 04:32:53.205 DEBG [sc] cr2: logging in
9112026-05-11T04:32:53.351ZMay 11 04:32:53.338 DEBG [sc] cr2: executing command `docker pause ceos`
9122026-05-11T04:32:55.470ZMay 11 04:32:55.456 INFO phase 4: resume bfdd on cr1
9132026-05-11T04:32:55.470ZMay 11 04:32:55.456 INFO cr1: resuming frr bfdd
9142026-05-11T04:32:55.495ZMay 11 04:32:55.457 DEBG [sc] cr1: starting
9152026-05-11T04:32:55.495ZMay 11 04:32:55.457 DEBG [sc] cr1: connecting to [::1]:35206
9162026-05-11T04:32:55.495ZMay 11 04:32:55.457 DEBG [sc] cr1 waiting for prompt
9172026-05-11T04:32:55.495ZMay 11 04:32:55.468 DEBG [sc] cr1: logging in
9182026-05-11T04:32:55.603ZMay 11 04:32:55.589 DEBG [sc] cr1: executing command `pkill -CONT bfdd`
9192026-05-11T04:32:57.690ZMay 11 04:32:57.677 INFO cr1: executing frr script show bfd peers json
9202026-05-11T04:32:57.691ZMay 11 04:32:57.677 DEBG [sc] cr1: starting
9212026-05-11T04:32:57.691ZMay 11 04:32:57.677 DEBG [sc] cr1: connecting to [::1]:35206
9222026-05-11T04:32:57.715ZMay 11 04:32:57.678 DEBG [sc] cr1 waiting for prompt
9232026-05-11T04:32:57.715ZMay 11 04:32:57.686 DEBG [sc] cr1: logging in
9242026-05-11T04:32:57.843ZMay 11 04:32:57.830 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9252026-05-11T04:32:59.983ZMay 11 04:32:59.969 INFO cr1: executing frr script show bfd peers json
9262026-05-11T04:32:59.983ZMay 11 04:32:59.970 DEBG [sc] cr1: starting
9272026-05-11T04:32:59.983ZMay 11 04:32:59.970 DEBG [sc] cr1: connecting to [::1]:35206
9282026-05-11T04:33:00.007ZMay 11 04:32:59.970 DEBG [sc] cr1 waiting for prompt
9292026-05-11T04:33:00.007ZMay 11 04:32:59.981 DEBG [sc] cr1: logging in
9302026-05-11T04:33:00.116ZMay 11 04:33:00.102 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9312026-05-11T04:33:02.253ZMay 11 04:33:02.240 INFO phase 5: unpause ceos on cr2
9322026-05-11T04:33:02.254ZMay 11 04:33:02.240 INFO cr2: unpausing ceos
9332026-05-11T04:33:02.254ZMay 11 04:33:02.240 DEBG [sc] cr2: starting
9342026-05-11T04:33:02.254ZMay 11 04:33:02.240 DEBG [sc] cr2: connecting to [::1]:62803
9352026-05-11T04:33:02.278ZMay 11 04:33:02.240 DEBG [sc] cr2 waiting for prompt
9362026-05-11T04:33:02.278ZMay 11 04:33:02.252 DEBG [sc] cr2: logging in
9372026-05-11T04:33:02.397ZMay 11 04:33:02.383 DEBG [sc] cr2: executing command `docker unpause ceos`
9382026-05-11T04:33:04.528ZMay 11 04:33:04.514 INFO cr1: executing frr script show bfd peers json
9392026-05-11T04:33:04.528ZMay 11 04:33:04.514 DEBG [sc] cr1: starting
9402026-05-11T04:33:04.528ZMay 11 04:33:04.514 DEBG [sc] cr1: connecting to [::1]:35206
9412026-05-11T04:33:04.552ZMay 11 04:33:04.515 DEBG [sc] cr1 waiting for prompt
9422026-05-11T04:33:04.552ZMay 11 04:33:04.526 DEBG [sc] cr1: logging in
9432026-05-11T04:33:04.694ZMay 11 04:33:04.680 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9442026-05-11T04:33:06.831ZMay 11 04:33:06.817 INFO cr1: executing frr script show bfd peers json
9452026-05-11T04:33:06.831ZMay 11 04:33:06.817 DEBG [sc] cr1: starting
9462026-05-11T04:33:06.831ZMay 11 04:33:06.817 DEBG [sc] cr1: connecting to [::1]:35206
9472026-05-11T04:33:06.855ZMay 11 04:33:06.818 DEBG [sc] cr1 waiting for prompt
9482026-05-11T04:33:06.855ZMay 11 04:33:06.829 DEBG [sc] cr1: logging in
9492026-05-11T04:33:06.986ZMay 11 04:33:06.973 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9502026-05-11T04:33:09.139ZMay 11 04:33:09.125 INFO cr2: executing eos script show bfd peers | json
9512026-05-11T04:33:09.139ZMay 11 04:33:09.126 DEBG [sc] cr2: starting
9522026-05-11T04:33:09.139ZMay 11 04:33:09.126 DEBG [sc] cr2: connecting to [::1]:62803
9532026-05-11T04:33:09.163ZMay 11 04:33:09.126 DEBG [sc] cr2 waiting for prompt
9542026-05-11T04:33:09.163ZMay 11 04:33:09.138 DEBG [sc] cr2: logging in
9552026-05-11T04:33:09.282ZMay 11 04:33:09.269 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9562026-05-11T04:33:11.612ZMay 11 04:33:11.599 INFO cr2: executing eos script show bfd peers | json
9572026-05-11T04:33:11.612ZMay 11 04:33:11.599 DEBG [sc] cr2: starting
9582026-05-11T04:33:11.612ZMay 11 04:33:11.599 DEBG [sc] cr2: connecting to [::1]:62803
9592026-05-11T04:33:11.637ZMay 11 04:33:11.600 DEBG [sc] cr2 waiting for prompt
9602026-05-11T04:33:11.637ZMay 11 04:33:11.610 DEBG [sc] cr2: logging in
9612026-05-11T04:33:11.756ZMay 11 04:33:11.742 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9622026-05-11T04:33:14.105ZMay 11 04:33:14.092 INFO trio bfd static routing test passed 🎉
9632026-05-11T04:33:14.106ZMay 11 04:33:14.092 INFO destroying runner for deployment mgtriobfd
9642026-05-11T04:33:14.106ZMay 11 04:33:14.092 INFO destroying deployment mgtriobfd
9652026-05-11T04:33:14.106ZMay 11 04:33:14.092 INFO destroying nodes
9662026-05-11T04:33:14.217ZMay 11 04:33:14.203 INFO destroying links
9672026-05-11T04:33:14.217ZMay 11 04:33:14.203 INFO destroying link mgtriobfd_ox_sn_vnic0
9682026-05-11T04:33:14.241ZMay 11 04:33:14.205 INFO destroying link mgtriobfd_ox_sn_sim0
9692026-05-11T04:33:14.241ZMay 11 04:33:14.206 INFO destroying link mgtriobfd_cr1_vn_vnic0
9702026-05-11T04:33:15.222ZMay 11 04:33:15.209 INFO destroying link mgtriobfd_cr1_vn_sim0
9712026-05-11T04:33:15.247ZMay 11 04:33:15.210 INFO destroying link mgtriobfd_ox_sn_vnic1
9722026-05-11T04:33:15.247ZMay 11 04:33:15.211 INFO destroying link mgtriobfd_ox_sn_sim1
9732026-05-11T04:33:15.247ZMay 11 04:33:15.212 INFO destroying link mgtriobfd_cr2_vn_vnic0
9742026-05-11T04:33:15.247ZMay 11 04:33:15.213 INFO destroying link mgtriobfd_cr2_vn_sim0
9752026-05-11T04:33:15.247ZMay 11 04:33:15.214 INFO destroying external links
9762026-05-11T04:33:15.247ZMay 11 04:33:15.214 INFO destroying external link mgtriobfd_ox_vn_vnic2
9772026-05-11T04:33:15.247ZMay 11 04:33:15.215 INFO destroying external link mgtriobfd_cr1_vn_vnic1
9782026-05-11T04:33:15.247ZMay 11 04:33:15.216 INFO destroying external link mgtriobfd_cr2_vn_vnic1
9792026-05-11T04:33:15.247ZMay 11 04:33:15.217 INFO destroying images
9802026-05-11T04:33:15.708ZMay 11 04:33:15.694 INFO destroying workspace at .falcon
9812026-05-11T04:33:15.732Zprocess exited: duration 729160 ms, exit code 0
 
9822026-05-11T04:33:15.784Zfound 0 output files