01KR6PGBABYE1EDVV3VFMH1K99: falcon

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

Buildomat Job: 01KR6PGPDYKRGMDB09MPVT045A

Tags:

Output:

SEQ GLOBAL TIME DETAILS
12026-05-09T15:56:32.074Zjob dependencies complete; ready to run (waiting for 13 m 9 s)
22026-05-09T15:59:44.403Zjob assigned to worker 01KR6Q8S4E34914ZP6GSSYSF6V [factory edgar, gimlet/BRM42220060/554] (queued for 3 m 12 s)
32026-05-09T15:59:44.612Zdownloading input: /input/build/work/debug/ddmadm
42026-05-09T16:00:07.074Zdownloaded input: /input/build/work/debug/ddmadm
52026-05-09T16:00:07.074Zdownloading input: /input/build/work/debug/ddmd
62026-05-09T16:00:34.142Zdownloaded input: /input/build/work/debug/ddmd
72026-05-09T16:00:34.142Zdownloading input: /input/build/work/debug/mgadm
82026-05-09T16:01:00.775Zdownloaded input: /input/build/work/debug/mgadm
92026-05-09T16:01:00.775Zdownloading input: /input/build/work/debug/mgd
102026-05-09T16:01:31.218Zdownloaded input: /input/build/work/debug/mgd
112026-05-09T16:01:31.243Zdownloading input: /input/build/work/release/ddmadm
122026-05-09T16:01:33.366Zdownloaded input: /input/build/work/release/ddmadm
132026-05-09T16:01:33.366Zdownloading input: /input/build/work/release/ddmd
142026-05-09T16:01:35.996Zdownloaded input: /input/build/work/release/ddmd
152026-05-09T16:01:35.996Zdownloading input: /input/build/work/release/falcon-lab
162026-05-09T16:01:37.632Zdownloaded input: /input/build/work/release/falcon-lab
172026-05-09T16:01:37.632Zdownloading input: /input/build/work/release/mgadm
182026-05-09T16:01:40.194Zdownloaded input: /input/build/work/release/mgadm
192026-05-09T16:01:40.194Zdownloading input: /input/build/work/release/mgd
202026-05-09T16:01:43.568Zdownloaded input: /input/build/work/release/mgd
212026-05-09T16:01:43.593Zdownloading input: /input/build-interop/work/testbed.tar.gz
222026-05-09T16:01:52.337Zdownloaded input: /input/build-interop/work/testbed.tar.gz
232026-05-09T16:01:52.337Zdownloading input: /input/build-interop/work/dhcp-server
242026-05-09T16:01:54.606Zdownloaded input: /input/build-interop/work/dhcp-server
 
252026-05-09T16:01:54.606Zstarting task 0: "setup"
262026-05-09T16:01:54.630Z++ uname -s
272026-05-09T16:01:54.630Z+ kern=SunOS
282026-05-09T16:01:54.630Z+ build_user=build
292026-05-09T16:01:54.630Z+ build_uid=12345
302026-05-09T16:01:54.630Z+ work_dir=/work
312026-05-09T16:01:54.630Z+ input_dir=/input
322026-05-09T16:01:54.631Z+ [[ 0 == 12345 ]]
332026-05-09T16:01:54.631Z+ case "$kern" in
342026-05-09T16:01:54.631Z+ groupadd -g 12345 build
352026-05-09T16:01:54.655Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
362026-05-09T16:01:56.643Z+ zfs create -o mountpoint=/work rpool/work
372026-05-09T16:01:56.710Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
382026-05-09T16:01:56.734Z+ home_fs=
392026-05-09T16:01:56.734Z+ [[ '' == autofs ]]
402026-05-09T16:01:56.734Z+ mkdir -p /home/build
412026-05-09T16:01:56.734Z+ chown build:build /home/build /work
422026-05-09T16:01:58.725Z+ chmod 0700 /home/build /work
432026-05-09T16:01:58.749Zprocess exited: duration 4123 ms, exit code 0
 
442026-05-09T16:01:58.798Zstarting task 1: "authentication"
452026-05-09T16:01:58.894Zprocess exited: duration 96 ms, exit code 0
 
462026-05-09T16:01:58.943Zstarting task 2: "build"
472026-05-09T16:01:58.967Z+ set -e
482026-05-09T16:01:58.967Z+ banner zpool
492026-05-09T16:01:58.967Z
502026-05-09T16:01:58.967Z ###### ##### #### #### #
512026-05-09T16:01:58.967Z # # # # # # # #
522026-05-09T16:01:58.967Z # # # # # # # #
532026-05-09T16:01:58.967Z # ##### # # # # #
542026-05-09T16:01:58.967Z # # # # # # #
552026-05-09T16:01:58.967Z ###### # #### #### ######
562026-05-09T16:01:58.967Z
572026-05-09T16:01:58.968Z++ pfexec diskinfo -pH
582026-05-09T16:01:58.991Z++ sort -k8 -n -r
592026-05-09T16:01:58.992Z++ head -1
602026-05-09T16:01:58.992Z++ awk '{print $2}'
612026-05-09T16:01:59.019Z+ DISK=c9t0014EE81000BC57Cd0
622026-05-09T16:01:59.019Z+ export DISK
632026-05-09T16:01:59.044Z+ pfexec zpool create -o ashift=12 -f cpool c9t0014EE81000BC57Cd0
642026-05-09T16:01:59.091Z+ pfexec zfs create -o mountpoint=/ci cpool/ci
652026-05-09T16:01:59.116Z++ curl -s http://catacomb.eng.oxide.computer:12346/trim-me
662026-05-09T16:01:59.258Z+ [[ true =~ true ]]
672026-05-09T16:01:59.282Z+ pfexec zpool trim cpool
682026-05-09T16:01:59.282Z++ zpool status -t cpool
692026-05-09T16:01:59.306Z+ [[ ! pool: cpool
702026-05-09T16:01:59.307Z state: ONLINE
712026-05-09T16:01:59.307Z scan: none requested
722026-05-09T16:01:59.307Zconfig:
732026-05-09T16:01:59.307Z
742026-05-09T16:01:59.307Z NAME STATE READ WRITE CKSUM
752026-05-09T16:01:59.307Z cpool ONLINE 0 0 0
762026-05-09T16:01:59.307Z c9t0014EE81000BC57Cd0 ONLINE 0 0 0 (1% trimmed, started at May 9, 2026 at 04:01:59 PM UTC)
772026-05-09T16:01:59.307Z
782026-05-09T16:01:59.307Zerrors: No known data errors =~ 100% ]]
792026-05-09T16:01:59.307Z+ sleep 10
802026-05-09T16:02:09.292Z++ zpool status -t cpool
812026-05-09T16:02:09.316Z+ [[ ! pool: cpool
822026-05-09T16:02:09.316Z state: ONLINE
832026-05-09T16:02:09.316Z scan: none requested
842026-05-09T16:02:09.316Zconfig:
852026-05-09T16:02:09.316Z
862026-05-09T16:02:09.316Z NAME STATE READ WRITE CKSUM
872026-05-09T16:02:09.316Z cpool ONLINE 0 0 0
882026-05-09T16:02:09.316Z c9t0014EE81000BC57Cd0 ONLINE 0 0 0 (71% trimmed, started at May 9, 2026 at 04:01:59 PM UTC)
892026-05-09T16:02:09.316Z
902026-05-09T16:02:09.316Zerrors: No known data errors =~ 100% ]]
912026-05-09T16:02:09.316Z+ sleep 10
922026-05-09T16:02:19.306Z++ zpool status -t cpool
932026-05-09T16:02:19.330Z+ [[ ! pool: cpool
942026-05-09T16:02:19.331Z state: ONLINE
952026-05-09T16:02:19.331Z scan: none requested
962026-05-09T16:02:19.331Zconfig:
972026-05-09T16:02:19.331Z
982026-05-09T16:02:19.331Z NAME STATE READ WRITE CKSUM
992026-05-09T16:02:19.331Z cpool ONLINE 0 0 0
1002026-05-09T16:02:19.331Z c9t0014EE81000BC57Cd0 ONLINE 0 0 0 (100% trimmed, completed at May 9, 2026 at 04:02:13 PM UTC)
1012026-05-09T16:02:19.331Z
1022026-05-09T16:02:19.331Zerrors: No known data errors =~ 100% ]]
1032026-05-09T16:02:19.331Z+ pfexec chown 12345 /ci
1042026-05-09T16:02:19.331Z+ cd /ci
1052026-05-09T16:02:19.331Z+ export FALCON_DATASET=cpool/falcon
1062026-05-09T16:02:19.331Z+ FALCON_DATASET=cpool/falcon
1072026-05-09T16:02:19.331Z+ banner setup
1082026-05-09T16:02:19.331Z
1092026-05-09T16:02:19.331Z #### ###### ##### # # #####
1102026-05-09T16:02:19.331Z # # # # # # #
1112026-05-09T16:02:19.331Z #### ##### # # # # #
1122026-05-09T16:02:19.331Z # # # # # #####
1132026-05-09T16:02:19.331Z # # # # # # #
1142026-05-09T16:02:19.331Z #### ###### # #### #
1152026-05-09T16:02:19.331Z
1162026-05-09T16:02:19.331Z+ cp /input/build-interop/work/dhcp-server .
1172026-05-09T16:02:19.360Z+ cp /input/build/work/release/falcon-lab .
1182026-05-09T16:02:19.399Z+ cp /input/build/work/release/mgd .
1192026-05-09T16:02:19.479Z+ cp /input/build/work/release/ddmd .
1202026-05-09T16:02:19.539Z+ chmod +x dhcp-server falcon-lab mgd ddmd
1212026-05-09T16:02:19.563Z+ mkdir -p cargo-bay
1222026-05-09T16:02:19.563Z+ mv mgd cargo-bay/
1232026-05-09T16:02:19.563Z+ mv ddmd cargo-bay/
1242026-05-09T16:02:19.564Z+ export EXT_INTERFACE=igb0
1252026-05-09T16:02:19.564Z+ EXT_INTERFACE=igb0
1262026-05-09T16:02:19.564Z++ bmat address ls -f extra -Ho first
1272026-05-09T16:02:19.588Z+ first=10.151.7.164
1282026-05-09T16:02:19.588Z++ bmat address ls -f extra -Ho last
1292026-05-09T16:02:19.612Z+ last=10.151.7.227
1302026-05-09T16:02:19.612Z++ bmat address ls -f extra -Ho gateway
1312026-05-09T16:02:19.636Z+ gw=10.151.7.1
1322026-05-09T16:02:19.636Z++ ipadm show-addr igb0/dhcp -po ADDR
1332026-05-09T16:02:19.661Z++ sed 's#/.*##g'
1342026-05-09T16:02:19.661Z+ server=10.151.7.100
1352026-05-09T16:02:19.661Z+ RUST_LOG=debug
1362026-05-09T16:02:19.661Z+ pfexec ./falcon-lab run trio-unnumbered
1372026-05-09T16:02:19.661Z+ pfexec ./dhcp-server 10.151.7.164 10.151.7.227 10.151.7.1 10.151.7.100
1382026-05-09T16:02:19.685ZMay 09 16:02:19.652 DEBG using default route interface igb0
1392026-05-09T16:02:19.685ZMay 09 16:02:19.652 DEBG using default route interface igb0
1402026-05-09T16:02:19.685ZMay 09 16:02:19.652 DEBG using default route interface igb0
1412026-05-09T16:02:19.685ZMay 09 16:02:19.652 INFO launching runner: deployment(mgtriou) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
1422026-05-09T16:02:19.685ZMay 09 16:02:19.652 INFO starting preflight for deployment mgtriou
1432026-05-09T16:02:19.685ZMay 09 16:02:19.652 INFO propolis-server binary not found
1442026-05-09T16:02:19.685ZMay 09 16:02:19.652 INFO downloading propolis server rev 36f20be9bb4c3b362029237f5feb6377c982395f, writing to .falcon/bin/propolis-server
1452026-05-09T16:02:23.523ZMay 09 16:02:23.513 INFO ovmf fd not found
1462026-05-09T16:02:23.523ZMay 09 16:02:23.513 INFO downloading ovmf
1472026-05-09T16:02:23.912ZMay 09 16:02:23.902 INFO base image for helios-2.9 does not exist, attempting to install
1482026-05-09T16:02:23.912ZMay 09 16:02:23.902 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/helios-2.9_0.raw.xz
1492026-05-09T16:02:52.066ZMay 09 16:02:52.059 INFO extracting image to /tmp/helios-2.9_0.raw
1502026-05-09T16:03:25.529ZMay 09 16:03:25.523 INFO creating zvol cpool/falcon/img/helios-2.9 of size 4508880896
1512026-05-09T16:03:25.579ZMay 09 16:03:25.573 INFO copying image data to zvol
1522026-05-09T16:03:36.222ZMay 09 16:03:36.215 INFO creating zfs snapshot cpool/falcon/img/helios-2.9@base
1532026-05-09T16:03:39.557ZMay 09 16:03:39.551 INFO base image for debian-13.2 does not exist, attempting to install
1542026-05-09T16:03:39.557ZMay 09 16:03:39.551 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz
1552026-05-09T16:04:00.332ZMay 09 16:04:00.327 INFO extracting image to /tmp/debian-13.2_0.raw
1562026-05-09T16:04:21.200ZMay 09 16:04:21.194 INFO creating zvol cpool/falcon/img/debian-13.2 of size 3221229568
1572026-05-09T16:04:21.225ZMay 09 16:04:21.220 INFO copying image data to zvol
1582026-05-09T16:04:27.580ZMay 09 16:04:27.575 INFO creating zfs snapshot cpool/falcon/img/debian-13.2@base
1592026-05-09T16:04:31.386ZMay 09 16:04:31.381 INFO base image for eos-4.35 does not exist, attempting to install
1602026-05-09T16:04:31.386ZMay 09 16:04:31.381 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz
1612026-05-09T16:05:14.536ZMay 09 16:05:14.531 INFO extracting image to /tmp/eos-4.35_0.raw
1622026-05-09T16:06:38.142ZMay 09 16:06:38.133 INFO creating zvol cpool/falcon/img/eos-4.35 of size 21474840576
1632026-05-09T16:06:38.167ZMay 09 16:06:38.159 INFO copying image data to zvol
1642026-05-09T16:07:34.587ZMay 09 16:07:34.575 INFO creating zfs snapshot cpool/falcon/img/eos-4.35@base
1652026-05-09T16:07:37.835ZMay 09 16:07:37.823 INFO creating links
1662026-05-09T16:07:37.835ZMay 09 16:07:37.823 DEBG destroying link mgtriou_ox_sn_vnic0
1672026-05-09T16:07:37.859ZMay 09 16:07:37.823 DEBG destroying link mgtriou_ox_sn_sim0
1682026-05-09T16:07:37.859ZMay 09 16:07:37.823 INFO creating simnet link 'mgtriou_ox_sn_sim0'
1692026-05-09T16:07:37.859ZMay 09 16:07:37.826 INFO creating vnic link 'mgtriou_ox_sn_vnic0'
1702026-05-09T16:07:37.859ZMay 09 16:07:37.834 DEBG link pair created
1712026-05-09T16:07:37.859ZMay 09 16:07:37.834 DEBG destroying link mgtriou_cr1_vn_vnic0
1722026-05-09T16:07:37.859ZMay 09 16:07:37.834 DEBG destroying link mgtriou_cr1_vn_sim0
1732026-05-09T16:07:37.859ZMay 09 16:07:37.834 INFO creating simnet link 'mgtriou_cr1_vn_sim0'
1742026-05-09T16:07:37.859ZMay 09 16:07:37.836 INFO creating vnic link 'mgtriou_cr1_vn_vnic0'
1752026-05-09T16:07:37.859ZMay 09 16:07:37.842 DEBG link pair created
1762026-05-09T16:07:37.859ZMay 09 16:07:37.842 DEBG destroying link mgtriou_ox_sn_vnic1
1772026-05-09T16:07:37.860ZMay 09 16:07:37.842 DEBG destroying link mgtriou_ox_sn_sim1
1782026-05-09T16:07:37.860ZMay 09 16:07:37.842 INFO creating simnet link 'mgtriou_ox_sn_sim1'
1792026-05-09T16:07:37.860ZMay 09 16:07:37.844 INFO creating vnic link 'mgtriou_ox_sn_vnic1'
1802026-05-09T16:07:37.884ZMay 09 16:07:37.850 DEBG link pair created
1812026-05-09T16:07:37.884ZMay 09 16:07:37.850 DEBG destroying link mgtriou_cr2_vn_vnic0
1822026-05-09T16:07:37.884ZMay 09 16:07:37.850 DEBG destroying link mgtriou_cr2_vn_sim0
1832026-05-09T16:07:37.884ZMay 09 16:07:37.850 INFO creating simnet link 'mgtriou_cr2_vn_sim0'
1842026-05-09T16:07:37.884ZMay 09 16:07:37.852 INFO creating vnic link 'mgtriou_cr2_vn_vnic0'
1852026-05-09T16:07:37.884ZMay 09 16:07:37.859 DEBG link pair created
1862026-05-09T16:07:37.884ZMay 09 16:07:37.859 INFO creating external links
1872026-05-09T16:07:37.884ZMay 09 16:07:37.859 DEBG destroying external link mgtriou_ox_vn_vnic2
1882026-05-09T16:07:37.884ZMay 09 16:07:37.859 INFO creating external link mgtriou_ox_vn_vnic2
1892026-05-09T16:07:37.884ZMay 09 16:07:37.861 DEBG external link mgtriou_ox_vn_vnic2@igb0 created
1902026-05-09T16:07:37.884ZMay 09 16:07:37.861 DEBG destroying external link mgtriou_cr1_vn_vnic1
1912026-05-09T16:07:37.884ZMay 09 16:07:37.861 INFO creating external link mgtriou_cr1_vn_vnic1
1922026-05-09T16:07:37.884ZMay 09 16:07:37.862 DEBG external link mgtriou_cr1_vn_vnic1@igb0 created
1932026-05-09T16:07:37.884ZMay 09 16:07:37.862 DEBG destroying external link mgtriou_cr2_vn_vnic1
1942026-05-09T16:07:37.884ZMay 09 16:07:37.862 INFO creating external link mgtriou_cr2_vn_vnic1
1952026-05-09T16:07:37.884ZMay 09 16:07:37.863 DEBG external link mgtriou_cr2_vn_vnic1@igb0 created
1962026-05-09T16:07:37.884ZMay 09 16:07:37.863 INFO creating nodes
1972026-05-09T16:07:37.884ZMay 09 16:07:37.863 INFO ox: launching node
1982026-05-09T16:07:37.884ZMay 09 16:07:37.866 INFO cr1: launching node
1992026-05-09T16:07:37.884ZMay 09 16:07:37.868 INFO cr2: launching node
2002026-05-09T16:07:37.909ZMay 09 16:07:37.882 INFO launched instance ox with pid 857 on port 50465
2012026-05-09T16:07:37.909ZMay 09 16:07:37.882 INFO ox: instance ensure
2022026-05-09T16:07:37.909ZMay 09 16:07:37.883 INFO launched instance cr1 with pid 858 on port 42295
2032026-05-09T16:07:37.909ZMay 09 16:07:37.883 INFO cr1: instance ensure
2042026-05-09T16:07:37.909ZMay 09 16:07:37.883 INFO launched instance cr2 with pid 859 on port 40093
2052026-05-09T16:07:37.909ZMay 09 16:07:37.883 INFO cr2: instance ensure
2062026-05-09T16:07:40.135ZMay 09 16:07:40.123 INFO cr1: instance ensure completed after 0 retries
2072026-05-09T16:07:40.135ZMay 09 16:07:40.123 INFO cr1: instance run
2082026-05-09T16:07:40.160ZMay 09 16:07:40.123 DEBG [sc] cr1: starting
2092026-05-09T16:07:40.160ZMay 09 16:07:40.123 DEBG [sc] cr1: connecting to [::1]:42295
2102026-05-09T16:07:40.160ZMay 09 16:07:40.124 DEBG [sc] cr1 waiting for prompt
2112026-05-09T16:07:40.226ZMay 09 16:07:40.214 INFO cr2: instance ensure completed after 0 retries
2122026-05-09T16:07:40.227ZMay 09 16:07:40.214 INFO cr2: instance run
2132026-05-09T16:07:40.251ZMay 09 16:07:40.215 DEBG [sc] cr2: starting
2142026-05-09T16:07:40.251ZMay 09 16:07:40.215 DEBG [sc] cr2: connecting to [::1]:40093
2152026-05-09T16:07:40.251ZMay 09 16:07:40.216 DEBG [sc] cr2 waiting for prompt
2162026-05-09T16:07:40.251ZMay 09 16:07:40.222 INFO ox: instance ensure completed after 0 retries
2172026-05-09T16:07:40.251ZMay 09 16:07:40.222 INFO ox: instance run
2182026-05-09T16:07:40.251ZMay 09 16:07:40.222 DEBG [sc] ox: starting
2192026-05-09T16:07:40.251ZMay 09 16:07:40.222 DEBG [sc] ox: connecting to [::1]:50465
2202026-05-09T16:07:40.251ZMay 09 16:07:40.223 DEBG [sc] ox waiting for prompt
2212026-05-09T16:07:57.149ZMay 09 16:07:57.137 DEBG [sc] cr1: logging in
2222026-05-09T16:07:57.547ZMay 09 16:07:57.535 INFO cr1: mounting /opt/cargo-bay
2232026-05-09T16:07:57.547ZMay 09 16:07:57.535 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2242026-05-09T16:07:57.571ZMay 09 16:07:57.557 DEBG [sc] cr1: executing command `cd`
2252026-05-09T16:07:57.596ZMay 09 16:07:57.568 INFO cr1: finished mounting /opt/cargo-bay
2262026-05-09T16:07:57.596ZMay 09 16:07:57.568 DEBG [sc] cr1: executing command `hostname cr1`
2272026-05-09T16:07:57.596ZMay 09 16:07:57.579 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
2282026-05-09T16:07:57.620ZMay 09 16:07:57.591 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
2292026-05-09T16:07:57.620ZMay 09 16:07:57.603 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
2302026-05-09T16:07:57.644ZMay 09 16:07:57.613 INFO cr1: logging out
2312026-05-09T16:07:59.682ZMay 09 16:07:59.670 INFO cr1: logged out
2322026-05-09T16:08:00.788ZMay 09 16:08:00.776 DEBG [sc] ox: logging in
2332026-05-09T16:08:00.979ZMay 09 16:08:00.967 INFO ox: mounting /opt/cargo-bay
2342026-05-09T16:08:00.979ZMay 09 16:08:00.967 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2352026-05-09T16:08:01.755ZMay 09 16:08:01.743 DEBG [sc] cr2: logging in
2362026-05-09T16:08:02.074ZMay 09 16:08:02.062 DEBG [sc] ox: executing command `cd`
2372026-05-09T16:08:02.099ZMay 09 16:08:02.073 INFO ox: finished mounting /opt/cargo-bay
2382026-05-09T16:08:02.099ZMay 09 16:08:02.073 DEBG [sc] ox: executing command `hostname ox`
2392026-05-09T16:08:02.099ZMay 09 16:08:02.085 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
2402026-05-09T16:08:02.123ZMay 09 16:08:02.096 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
2412026-05-09T16:08:02.123ZMay 09 16:08:02.107 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
2422026-05-09T16:08:02.147ZMay 09 16:08:02.118 INFO ox: logging out
2432026-05-09T16:08:02.171ZMay 09 16:08:02.145 INFO cr2: mounting /opt/cargo-bay
2442026-05-09T16:08:02.171ZMay 09 16:08:02.145 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2452026-05-09T16:08:02.195ZMay 09 16:08:02.167 DEBG [sc] cr2: executing command `cd`
2462026-05-09T16:08:02.195ZMay 09 16:08:02.177 INFO cr2: finished mounting /opt/cargo-bay
2472026-05-09T16:08:02.195ZMay 09 16:08:02.177 DEBG [sc] cr2: executing command `hostname cr2`
2482026-05-09T16:08:02.220ZMay 09 16:08:02.189 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
2492026-05-09T16:08:02.220ZMay 09 16:08:02.200 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
2502026-05-09T16:08:02.220ZMay 09 16:08:02.206 INFO ox: logged out
2512026-05-09T16:08:02.244ZMay 09 16:08:02.211 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
2522026-05-09T16:08:02.244ZMay 09 16:08:02.222 INFO cr2: logging out
2532026-05-09T16:08:05.236ZMay 09 16:08:05.224 INFO cr2: logged out
2542026-05-09T16:08:05.260ZMay 09 16:08:05.224 DEBG [sc] ox: starting
2552026-05-09T16:08:05.260ZMay 09 16:08:05.224 DEBG [sc] ox: connecting to [::1]:50465
2562026-05-09T16:08:05.260ZMay 09 16:08:05.225 DEBG [sc] ox waiting for prompt
2572026-05-09T16:08:05.260ZMay 09 16:08:05.236 DEBG [sc] ox: logging in
2582026-05-09T16:08:05.336ZMay 09 16:08:05.324 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
2592026-05-09T16:08:11.026ZMay 09 16:08:11.014 DEBG [sc] ox: starting
2602026-05-09T16:08:11.026ZMay 09 16:08:11.014 DEBG [sc] ox: connecting to [::1]:50465
2612026-05-09T16:08:11.051ZMay 09 16:08:11.015 DEBG [sc] ox waiting for prompt
2622026-05-09T16:08:11.051ZMay 09 16:08:11.025 DEBG [sc] ox: logging in
2632026-05-09T16:08:11.115ZMay 09 16:08:11.103 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
2642026-05-09T16:08:11.203ZMay 09 16:08:11.191 DEBG [sc] ox: starting
2652026-05-09T16:08:11.203ZMay 09 16:08:11.191 DEBG [sc] ox: connecting to [::1]:50465
2662026-05-09T16:08:11.228ZMay 09 16:08:11.192 DEBG [sc] ox waiting for prompt
2672026-05-09T16:08:11.228ZMay 09 16:08:11.202 DEBG [sc] ox: logging in
2682026-05-09T16:08:11.302ZMay 09 16:08:11.290 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
2692026-05-09T16:08:11.369ZMay 09 16:08:11.356 INFO cr1: installing frr
2702026-05-09T16:08:11.369ZMay 09 16:08:11.357 INFO waiting for ceos to initialize
2712026-05-09T16:08:11.369ZMay 09 16:08:11.357 INFO ox: setting up npuvm
2722026-05-09T16:08:11.393ZMay 09 16:08:11.357 DEBG [sc] cr1: starting
2732026-05-09T16:08:11.393ZMay 09 16:08:11.357 DEBG [sc] cr1: connecting to [::1]:42295
2742026-05-09T16:08:11.393ZMay 09 16:08:11.357 DEBG [sc] cr2: starting
2752026-05-09T16:08:11.393ZMay 09 16:08:11.357 DEBG [sc] cr2: connecting to [::1]:40093
2762026-05-09T16:08:11.393ZMay 09 16:08:11.357 DEBG [sc] ox: starting
2772026-05-09T16:08:11.393ZMay 09 16:08:11.357 DEBG [sc] ox: connecting to [::1]:50465
2782026-05-09T16:08:11.393ZMay 09 16:08:11.357 DEBG [sc] ox waiting for prompt
2792026-05-09T16:08:11.393ZMay 09 16:08:11.357 DEBG [sc] cr1 waiting for prompt
2802026-05-09T16:08:11.393ZMay 09 16:08:11.357 DEBG [sc] cr2 waiting for prompt
2812026-05-09T16:08:11.393ZMay 09 16:08:11.368 DEBG [sc] cr1: logging in
2822026-05-09T16:08:11.393ZMay 09 16:08:11.368 DEBG [sc] ox: logging in
2832026-05-09T16:08:11.393ZMay 09 16:08:11.369 DEBG [sc] cr2: logging in
2842026-05-09T16:08:11.458ZMay 09 16:08:11.446 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
2852026-05-09T16:08:11.523ZMay 09 16:08:11.511 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
2862026-05-09T16:08:11.741ZMay 09 16:08:11.729 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
2872026-05-09T16:08:13.783ZMay 09 16:08:13.771 INFO cr2: executing eos script show version
2882026-05-09T16:08:13.807ZMay 09 16:08:13.771 DEBG [sc] cr2: starting
2892026-05-09T16:08:13.807ZMay 09 16:08:13.771 DEBG [sc] cr2: connecting to [::1]:40093
2902026-05-09T16:08:13.807ZMay 09 16:08:13.771 DEBG [sc] cr2 waiting for prompt
2912026-05-09T16:08:13.807ZMay 09 16:08:13.782 DEBG [sc] cr2: logging in
2922026-05-09T16:08:13.949ZMay 09 16:08:13.937 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
2932026-05-09T16:08:18.808ZMay 09 16:08:18.794 DEBG [sc] ox: starting
2942026-05-09T16:08:18.808ZMay 09 16:08:18.794 DEBG [sc] ox: connecting to [::1]:50465
2952026-05-09T16:08:18.832ZMay 09 16:08:18.795 DEBG [sc] ox waiting for prompt
2962026-05-09T16:08:18.832ZMay 09 16:08:18.805 DEBG [sc] ox: logging in
2972026-05-09T16:08:18.894ZMay 09 16:08:18.882 DEBG [sc] ox: executing command `chmod +x npuvm`
2982026-05-09T16:08:18.960ZMay 09 16:08:18.948 DEBG [sc] ox: starting
2992026-05-09T16:08:18.960ZMay 09 16:08:18.948 DEBG [sc] ox: connecting to [::1]:50465
3002026-05-09T16:08:18.985ZMay 09 16:08:18.949 DEBG [sc] ox waiting for prompt
3012026-05-09T16:08:18.985ZMay 09 16:08:18.959 DEBG [sc] ox: logging in
3022026-05-09T16:08:19.059ZMay 09 16:08:19.047 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
3032026-05-09T16:08:22.808ZMay 09 16:08:22.796 DEBG [sc] cr2: starting
3042026-05-09T16:08:22.808ZMay 09 16:08:22.796 DEBG [sc] cr2: connecting to [::1]:40093
3052026-05-09T16:08:22.832ZMay 09 16:08:22.796 DEBG [sc] cr2 waiting for prompt
3062026-05-09T16:08:22.832ZMay 09 16:08:22.806 DEBG [sc] cr2: logging in
3072026-05-09T16:08:22.972ZMay 09 16:08:22.960 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3082026-05-09T16:08:25.092ZMay 09 16:08:25.080 INFO cr2: executing eos script show version
3092026-05-09T16:08:25.092ZMay 09 16:08:25.080 DEBG [sc] cr2: starting
3102026-05-09T16:08:25.092ZMay 09 16:08:25.080 DEBG [sc] cr2: connecting to [::1]:40093
3112026-05-09T16:08:25.116ZMay 09 16:08:25.080 DEBG [sc] cr2 waiting for prompt
3122026-05-09T16:08:25.117ZMay 09 16:08:25.092 DEBG [sc] cr2: logging in
3132026-05-09T16:08:25.292ZMay 09 16:08:25.280 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3142026-05-09T16:08:27.655ZMay 09 16:08:27.643 DEBG [sc] cr2: starting
3152026-05-09T16:08:27.655ZMay 09 16:08:27.643 DEBG [sc] cr2: connecting to [::1]:40093
3162026-05-09T16:08:27.679ZMay 09 16:08:27.643 DEBG [sc] cr2 waiting for prompt
3172026-05-09T16:08:27.679ZMay 09 16:08:27.654 DEBG [sc] cr2: logging in
3182026-05-09T16:08:27.819ZMay 09 16:08:27.807 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3192026-05-09T16:08:29.954ZMay 09 16:08:29.942 INFO cr2: executing eos script show version
3202026-05-09T16:08:29.954ZMay 09 16:08:29.942 DEBG [sc] cr2: starting
3212026-05-09T16:08:29.954ZMay 09 16:08:29.942 DEBG [sc] cr2: connecting to [::1]:40093
3222026-05-09T16:08:29.978ZMay 09 16:08:29.942 DEBG [sc] cr2 waiting for prompt
3232026-05-09T16:08:29.978ZMay 09 16:08:29.952 DEBG [sc] cr2: logging in
3242026-05-09T16:08:30.108ZMay 09 16:08:30.096 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3252026-05-09T16:08:32.610ZMay 09 16:08:32.598 INFO cr2: executing eos script
3262026-05-09T16:08:32.610Z enable
3272026-05-09T16:08:32.610Z configure
3282026-05-09T16:08:32.610Z ipv6 unicast-routing
3292026-05-09T16:08:32.610Z ip routing ipv6 interfaces
3302026-05-09T16:08:32.610Z ip routing
3312026-05-09T16:08:32.610Z ip route 1.2.3.0/24 null0
3322026-05-09T16:08:32.610Z ipv6 route fd99::/64 null0
3332026-05-09T16:08:32.611Z interface et1
3342026-05-09T16:08:32.611Z no switchport
3352026-05-09T16:08:32.611Z ipv6 enable
3362026-05-09T16:08:32.611Z
3372026-05-09T16:08:32.611Z router bgp 45
3382026-05-09T16:08:32.611Z router-id 1.2.3.1
3392026-05-09T16:08:32.611Z no bgp default ipv4-unicast
3402026-05-09T16:08:32.611Z timers bgp 2 6
3412026-05-09T16:08:32.611Z neighbor ebgp peer group
3422026-05-09T16:08:32.611Z neighbor ebgp remote-as 33
3432026-05-09T16:08:32.611Z neighbor interface Et1 peer-group ebgp
3442026-05-09T16:08:32.611Z address-family ipv4
3452026-05-09T16:08:32.611Z neighbor ebgp activate
3462026-05-09T16:08:32.611Z neighbor ebgp next-hop address-family ipv6 originate
3472026-05-09T16:08:32.611Z network 1.2.3.0/24
3482026-05-09T16:08:32.611Z exit
3492026-05-09T16:08:32.611Z address-family ipv6
3502026-05-09T16:08:32.611Z neighbor ebgp activate
3512026-05-09T16:08:32.611Z neighbor ebgp next-hop address-family ipv6 originate
3522026-05-09T16:08:32.611Z network fd99::/64
3532026-05-09T16:08:32.611Z exit
3542026-05-09T16:08:32.611Z exit
3552026-05-09T16:08:32.611Z
3562026-05-09T16:08:32.611ZMay 09 16:08:32.598 DEBG [sc] cr2: starting
3572026-05-09T16:08:32.611ZMay 09 16:08:32.598 DEBG [sc] cr2: connecting to [::1]:40093
3582026-05-09T16:08:32.636ZMay 09 16:08:32.599 DEBG [sc] cr2 waiting for prompt
3592026-05-09T16:08:32.636ZMay 09 16:08:32.608 DEBG [sc] cr2: logging in
3602026-05-09T16:08:32.764ZMay 09 16:08:32.752 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
3612026-05-09T16:08:32.764Z enable
3622026-05-09T16:08:32.764Z configure
3632026-05-09T16:08:32.765Z ipv6 unicast-routing
3642026-05-09T16:08:32.765Z ip routing ipv6 interfaces
3652026-05-09T16:08:32.765Z ip routing
3662026-05-09T16:08:32.765Z ip route 1.2.3.0/24 null0
3672026-05-09T16:08:32.765Z ipv6 route fd99::/64 null0
3682026-05-09T16:08:32.765Z interface et1
3692026-05-09T16:08:32.765Z no switchport
3702026-05-09T16:08:32.765Z ipv6 enable
3712026-05-09T16:08:32.765Z
3722026-05-09T16:08:32.765Z router bgp 45
3732026-05-09T16:08:32.765Z router-id 1.2.3.1
3742026-05-09T16:08:32.765Z no bgp default ipv4-unicast
3752026-05-09T16:08:32.765Z timers bgp 2 6
3762026-05-09T16:08:32.765Z neighbor ebgp peer group
3772026-05-09T16:08:32.765Z neighbor ebgp remote-as 33
3782026-05-09T16:08:32.765Z neighbor interface Et1 peer-group ebgp
3792026-05-09T16:08:32.765Z address-family ipv4
3802026-05-09T16:08:32.765Z neighbor ebgp activate
3812026-05-09T16:08:32.765Z neighbor ebgp next-hop address-family ipv6 originate
3822026-05-09T16:08:32.765Z network 1.2.3.0/24
3832026-05-09T16:08:32.765Z exit
3842026-05-09T16:08:32.765Z address-family ipv6
3852026-05-09T16:08:32.765Z neighbor ebgp activate
3862026-05-09T16:08:32.765Z neighbor ebgp next-hop address-family ipv6 originate
3872026-05-09T16:08:32.765Z network fd99::/64
3882026-05-09T16:08:32.765Z exit
3892026-05-09T16:08:32.765Z exit
3902026-05-09T16:08:32.765Z '`
3912026-05-09T16:08:49.473ZMay 09 16:08:49.461 INFO cr1: enabling frr daemon bgpd
3922026-05-09T16:08:49.473ZMay 09 16:08:49.461 DEBG [sc] cr1: starting
3932026-05-09T16:08:49.473ZMay 09 16:08:49.461 DEBG [sc] cr1: connecting to [::1]:42295
3942026-05-09T16:08:49.522ZMay 09 16:08:49.461 DEBG [sc] cr1 waiting for prompt
3952026-05-09T16:08:49.546ZMay 09 16:08:49.471 DEBG [sc] cr1: logging in
3962026-05-09T16:08:49.628ZMay 09 16:08:49.616 DEBG [sc] cr1: executing command `sed -i 's/bgpd=no/bgpd=yes/g' /etc/frr/daemons`
3972026-05-09T16:08:51.702ZMay 09 16:08:51.690 DEBG [sc] cr1: starting
3982026-05-09T16:08:51.702ZMay 09 16:08:51.690 DEBG [sc] cr1: connecting to [::1]:42295
3992026-05-09T16:08:51.727ZMay 09 16:08:51.691 DEBG [sc] cr1 waiting for prompt
4002026-05-09T16:08:51.727ZMay 09 16:08:51.701 DEBG [sc] cr1: logging in
4012026-05-09T16:08:51.845ZMay 09 16:08:51.833 DEBG [sc] cr1: executing command `systemctl restart frr`
4022026-05-09T16:08:59.502ZMay 09 16:08:59.468 INFO cr1: executing frr script
4032026-05-09T16:08:59.502Z configure
4042026-05-09T16:08:59.502Z ip forwarding
4052026-05-09T16:08:59.502Z ipv6 forwarding
4062026-05-09T16:08:59.502Z ip route 1.2.3.0/24 null0
4072026-05-09T16:08:59.502Z ipv6 route fd99::/64 null0
4082026-05-09T16:08:59.502Z router bgp 44
4092026-05-09T16:08:59.502Z no bgp ebgp-requires-policy
4102026-05-09T16:08:59.502Z timers bgp 2 6
4112026-05-09T16:08:59.502Z neighbor enp0s8 interface remote-as external
4122026-05-09T16:08:59.502Z neighbor enp0s8 timers connect 1
4132026-05-09T16:08:59.502Z address-family ipv4 unicast
4142026-05-09T16:08:59.502Z network 1.2.3.0/24
4152026-05-09T16:08:59.502Z neighbor enp0s8 activate
4162026-05-09T16:08:59.502Z exit-address-family
4172026-05-09T16:08:59.502Z address-family ipv6 unicast
4182026-05-09T16:08:59.502Z network fd99::/64
4192026-05-09T16:08:59.502Z neighbor enp0s8 activate
4202026-05-09T16:08:59.502Z exit-address-family
4212026-05-09T16:08:59.503Z exit
4222026-05-09T16:08:59.503Z
4232026-05-09T16:08:59.503ZMay 09 16:08:59.468 DEBG [sc] cr1: starting
4242026-05-09T16:08:59.503ZMay 09 16:08:59.468 DEBG [sc] cr1: connecting to [::1]:42295
4252026-05-09T16:08:59.503ZMay 09 16:08:59.469 DEBG [sc] cr1 waiting for prompt
4262026-05-09T16:08:59.503ZMay 09 16:08:59.480 DEBG [sc] cr1: logging in
4272026-05-09T16:08:59.612ZMay 09 16:08:59.600 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 ' '`
4282026-05-09T16:10:06.775ZMay 09 16:10:06.763 DEBG [sc] ox: starting
4292026-05-09T16:10:06.775ZMay 09 16:10:06.763 DEBG [sc] ox: connecting to [::1]:50465
4302026-05-09T16:10:06.799ZMay 09 16:10:06.764 DEBG [sc] ox waiting for prompt
4312026-05-09T16:10:06.799ZMay 09 16:10:06.774 DEBG [sc] ox: logging in
4322026-05-09T16:10:06.864ZMay 09 16:10:06.853 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
4332026-05-09T16:10:07.112ZMay 09 16:10:07.100 DEBG [sc] ox: starting
4342026-05-09T16:10:07.112ZMay 09 16:10:07.100 DEBG [sc] ox: connecting to [::1]:50465
4352026-05-09T16:10:07.137ZMay 09 16:10:07.100 DEBG [sc] ox waiting for prompt
4362026-05-09T16:10:07.137ZMay 09 16:10:07.112 DEBG [sc] ox: logging in
4372026-05-09T16:10:07.201ZMay 09 16:10:07.189 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4382026-05-09T16:10:08.226ZMay 09 16:10:08.213 DEBG [sc] ox: starting
4392026-05-09T16:10:08.226ZMay 09 16:10:08.213 DEBG [sc] ox: connecting to [::1]:50465
4402026-05-09T16:10:08.250ZMay 09 16:10:08.214 DEBG [sc] ox waiting for prompt
4412026-05-09T16:10:08.251ZMay 09 16:10:08.214 DEBG [sc] ox: logging in
4422026-05-09T16:10:08.305ZMay 09 16:10:08.293 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4432026-05-09T16:10:08.360ZMay 09 16:10:08.348 DEBG [sc] ox: starting
4442026-05-09T16:10:08.360ZMay 09 16:10:08.348 DEBG [sc] ox: connecting to [::1]:50465
4452026-05-09T16:10:08.385ZMay 09 16:10:08.349 DEBG [sc] ox waiting for prompt
4462026-05-09T16:10:08.385ZMay 09 16:10:08.359 DEBG [sc] ox: logging in
4472026-05-09T16:10:08.448ZMay 09 16:10:08.436 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
4482026-05-09T16:10:08.514ZMay 09 16:10:08.502 DEBG [sc] ox: starting
4492026-05-09T16:10:08.514ZMay 09 16:10:08.502 DEBG [sc] ox: connecting to [::1]:50465
4502026-05-09T16:10:08.539ZMay 09 16:10:08.503 DEBG [sc] ox waiting for prompt
4512026-05-09T16:10:08.539ZMay 09 16:10:08.513 DEBG [sc] ox: logging in
4522026-05-09T16:10:08.601ZMay 09 16:10:08.589 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
4532026-05-09T16:10:08.657ZMay 09 16:10:08.645 DEBG [sc] ox: starting
4542026-05-09T16:10:08.657ZMay 09 16:10:08.645 DEBG [sc] ox: connecting to [::1]:50465
4552026-05-09T16:10:08.682ZMay 09 16:10:08.646 DEBG [sc] ox waiting for prompt
4562026-05-09T16:10:08.682ZMay 09 16:10:08.655 DEBG [sc] ox: logging in
4572026-05-09T16:10:08.745ZMay 09 16:10:08.733 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
4582026-05-09T16:10:08.812ZMay 09 16:10:08.800 DEBG [sc] ox: starting
4592026-05-09T16:10:08.812ZMay 09 16:10:08.800 DEBG [sc] ox: connecting to [::1]:50465
4602026-05-09T16:10:08.837ZMay 09 16:10:08.801 DEBG [sc] ox waiting for prompt
4612026-05-09T16:10:08.837ZMay 09 16:10:08.812 DEBG [sc] ox: logging in
4622026-05-09T16:10:08.900ZMay 09 16:10:08.888 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
4632026-05-09T16:10:08.955ZMay 09 16:10:08.943 DEBG [sc] ox: starting
4642026-05-09T16:10:08.955ZMay 09 16:10:08.943 DEBG [sc] ox: connecting to [::1]:50465
4652026-05-09T16:10:08.980ZMay 09 16:10:08.944 DEBG [sc] ox waiting for prompt
4662026-05-09T16:10:08.980ZMay 09 16:10:08.954 DEBG [sc] ox: logging in
4672026-05-09T16:10:09.044ZMay 09 16:10:09.032 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
4682026-05-09T16:10:09.099ZMay 09 16:10:09.087 DEBG [sc] ox: starting
4692026-05-09T16:10:09.099ZMay 09 16:10:09.087 DEBG [sc] ox: connecting to [::1]:50465
4702026-05-09T16:10:09.123ZMay 09 16:10:09.088 DEBG [sc] ox waiting for prompt
4712026-05-09T16:10:09.123ZMay 09 16:10:09.098 DEBG [sc] ox: logging in
4722026-05-09T16:10:09.187ZMay 09 16:10:09.175 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
4732026-05-09T16:10:09.242ZMay 09 16:10:09.230 DEBG [sc] ox: starting
4742026-05-09T16:10:09.242ZMay 09 16:10:09.230 DEBG [sc] ox: connecting to [::1]:50465
4752026-05-09T16:10:09.267ZMay 09 16:10:09.231 DEBG [sc] ox waiting for prompt
4762026-05-09T16:10:09.267ZMay 09 16:10:09.241 DEBG [sc] ox: logging in
4772026-05-09T16:10:09.330ZMay 09 16:10:09.318 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
4782026-05-09T16:10:09.400ZMay 09 16:10:09.388 INFO adding BGP router to mgd
4792026-05-09T16:10:11.890ZMay 09 16:10:11.878 INFO cr1: executing frr script show ip bgp json
4802026-05-09T16:10:11.890ZMay 09 16:10:11.878 DEBG [sc] cr1: starting
4812026-05-09T16:10:11.890ZMay 09 16:10:11.878 DEBG [sc] cr1: connecting to [::1]:42295
4822026-05-09T16:10:11.914ZMay 09 16:10:11.878 DEBG [sc] cr1 waiting for prompt
4832026-05-09T16:10:11.914ZMay 09 16:10:11.890 DEBG [sc] cr1: logging in
4842026-05-09T16:10:12.224ZMay 09 16:10:12.212 DEBG [sc] cr1: executing command `vtysh -c 'show ip bgp json'`
4852026-05-09T16:10:14.344ZMay 09 16:10:14.332 INFO cr1: executing frr script show bgp json
4862026-05-09T16:10:14.344ZMay 09 16:10:14.332 DEBG [sc] cr1: starting
4872026-05-09T16:10:14.344ZMay 09 16:10:14.332 DEBG [sc] cr1: connecting to [::1]:42295
4882026-05-09T16:10:14.369ZMay 09 16:10:14.333 DEBG [sc] cr1 waiting for prompt
4892026-05-09T16:10:14.369ZMay 09 16:10:14.343 DEBG [sc] cr1: logging in
4902026-05-09T16:10:14.507ZMay 09 16:10:14.475 DEBG [sc] cr1: executing command `vtysh -c 'show bgp json'`
4912026-05-09T16:10:16.616ZMay 09 16:10:16.604 INFO cr2: executing eos script show ip bgp | json
4922026-05-09T16:10:16.616ZMay 09 16:10:16.604 DEBG [sc] cr2: starting
4932026-05-09T16:10:16.616ZMay 09 16:10:16.604 DEBG [sc] cr2: connecting to [::1]:40093
4942026-05-09T16:10:16.641ZMay 09 16:10:16.605 DEBG [sc] cr2 waiting for prompt
4952026-05-09T16:10:16.641ZMay 09 16:10:16.616 DEBG [sc] cr2: logging in
4962026-05-09T16:10:16.991ZMay 09 16:10:16.978 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ip bgp | json'`
4972026-05-09T16:10:19.358ZMay 09 16:10:19.346 INFO cr2: executing eos script show ipv6 bgp | json
4982026-05-09T16:10:19.358ZMay 09 16:10:19.346 DEBG [sc] cr2: starting
4992026-05-09T16:10:19.358ZMay 09 16:10:19.346 DEBG [sc] cr2: connecting to [::1]:40093
5002026-05-09T16:10:19.383ZMay 09 16:10:19.348 DEBG [sc] cr2 waiting for prompt
5012026-05-09T16:10:19.383ZMay 09 16:10:19.358 DEBG [sc] cr2: logging in
5022026-05-09T16:10:19.505ZMay 09 16:10:19.491 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ipv6 bgp | json'`
5032026-05-09T16:10:21.874ZMay 09 16:10:21.862 INFO trio bgp unnumbered test passed 🎉
5042026-05-09T16:10:21.875ZMay 09 16:10:21.862 INFO destroying runner for deployment mgtriou
5052026-05-09T16:10:21.875ZMay 09 16:10:21.862 INFO destroying deployment mgtriou
5062026-05-09T16:10:21.875ZMay 09 16:10:21.862 INFO destroying nodes
5072026-05-09T16:10:21.978ZMay 09 16:10:21.966 INFO destroying links
5082026-05-09T16:10:21.978ZMay 09 16:10:21.967 INFO destroying link mgtriou_ox_sn_vnic0
5092026-05-09T16:10:22.003ZMay 09 16:10:21.969 INFO destroying link mgtriou_ox_sn_sim0
5102026-05-09T16:10:22.003ZMay 09 16:10:21.970 INFO destroying link mgtriou_cr1_vn_vnic0
5112026-05-09T16:10:22.985ZMay 09 16:10:22.973 INFO destroying link mgtriou_cr1_vn_sim0
5122026-05-09T16:10:23.010ZMay 09 16:10:22.974 INFO destroying link mgtriou_ox_sn_vnic1
5132026-05-09T16:10:23.010ZMay 09 16:10:22.976 INFO destroying link mgtriou_ox_sn_sim1
5142026-05-09T16:10:23.010ZMay 09 16:10:22.977 INFO destroying link mgtriou_cr2_vn_vnic0
5152026-05-09T16:10:23.010ZMay 09 16:10:22.978 INFO destroying link mgtriou_cr2_vn_sim0
5162026-05-09T16:10:23.010ZMay 09 16:10:22.979 INFO destroying external links
5172026-05-09T16:10:23.010ZMay 09 16:10:22.979 INFO destroying external link mgtriou_ox_vn_vnic2
5182026-05-09T16:10:23.010ZMay 09 16:10:22.980 INFO destroying external link mgtriou_cr1_vn_vnic1
5192026-05-09T16:10:23.010ZMay 09 16:10:22.981 INFO destroying external link mgtriou_cr2_vn_vnic1
5202026-05-09T16:10:23.010ZMay 09 16:10:22.983 INFO destroying images
5212026-05-09T16:10:23.458ZMay 09 16:10:23.446 INFO destroying workspace at .falcon
5222026-05-09T16:10:23.482Z+ RUST_LOG=debug
5232026-05-09T16:10:23.482Z+ pfexec ./falcon-lab run trio-bfd-static-routing
5242026-05-09T16:10:23.507ZMay 09 16:10:23.487 DEBG using default route interface igb0
5252026-05-09T16:10:23.507ZMay 09 16:10:23.488 DEBG using default route interface igb0
5262026-05-09T16:10:23.507ZMay 09 16:10:23.488 DEBG using default route interface igb0
5272026-05-09T16:10:23.507ZMay 09 16:10:23.488 INFO launching runner: deployment(mgtriobfd) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
5282026-05-09T16:10:23.507ZMay 09 16:10:23.488 INFO starting preflight for deployment mgtriobfd
5292026-05-09T16:10:24.203ZMay 09 16:10:24.191 INFO creating links
5302026-05-09T16:10:24.203ZMay 09 16:10:24.191 DEBG destroying link mgtriobfd_ox_sn_vnic0
5312026-05-09T16:10:24.203ZMay 09 16:10:24.191 DEBG destroying link mgtriobfd_ox_sn_sim0
5322026-05-09T16:10:24.203ZMay 09 16:10:24.191 INFO creating simnet link 'mgtriobfd_ox_sn_sim0'
5332026-05-09T16:10:24.228ZMay 09 16:10:24.193 INFO creating vnic link 'mgtriobfd_ox_sn_vnic0'
5342026-05-09T16:10:24.228ZMay 09 16:10:24.200 DEBG link pair created
5352026-05-09T16:10:24.228ZMay 09 16:10:24.200 DEBG destroying link mgtriobfd_cr1_vn_vnic0
5362026-05-09T16:10:24.228ZMay 09 16:10:24.200 DEBG destroying link mgtriobfd_cr1_vn_sim0
5372026-05-09T16:10:24.228ZMay 09 16:10:24.200 INFO creating simnet link 'mgtriobfd_cr1_vn_sim0'
5382026-05-09T16:10:24.228ZMay 09 16:10:24.201 INFO creating vnic link 'mgtriobfd_cr1_vn_vnic0'
5392026-05-09T16:10:24.228ZMay 09 16:10:24.207 DEBG link pair created
5402026-05-09T16:10:24.228ZMay 09 16:10:24.207 DEBG destroying link mgtriobfd_ox_sn_vnic1
5412026-05-09T16:10:24.228ZMay 09 16:10:24.207 DEBG destroying link mgtriobfd_ox_sn_sim1
5422026-05-09T16:10:24.228ZMay 09 16:10:24.207 INFO creating simnet link 'mgtriobfd_ox_sn_sim1'
5432026-05-09T16:10:24.228ZMay 09 16:10:24.208 INFO creating vnic link 'mgtriobfd_ox_sn_vnic1'
5442026-05-09T16:10:24.228ZMay 09 16:10:24.214 DEBG link pair created
5452026-05-09T16:10:24.228ZMay 09 16:10:24.214 DEBG destroying link mgtriobfd_cr2_vn_vnic0
5462026-05-09T16:10:24.228ZMay 09 16:10:24.214 DEBG destroying link mgtriobfd_cr2_vn_sim0
5472026-05-09T16:10:24.228ZMay 09 16:10:24.214 INFO creating simnet link 'mgtriobfd_cr2_vn_sim0'
5482026-05-09T16:10:24.228ZMay 09 16:10:24.216 INFO creating vnic link 'mgtriobfd_cr2_vn_vnic0'
5492026-05-09T16:10:24.253ZMay 09 16:10:24.222 DEBG link pair created
5502026-05-09T16:10:24.253ZMay 09 16:10:24.222 INFO creating external links
5512026-05-09T16:10:24.253ZMay 09 16:10:24.222 DEBG destroying external link mgtriobfd_ox_vn_vnic2
5522026-05-09T16:10:24.253ZMay 09 16:10:24.222 INFO creating external link mgtriobfd_ox_vn_vnic2
5532026-05-09T16:10:24.253ZMay 09 16:10:24.223 DEBG external link mgtriobfd_ox_vn_vnic2@igb0 created
5542026-05-09T16:10:24.253ZMay 09 16:10:24.223 DEBG destroying external link mgtriobfd_cr1_vn_vnic1
5552026-05-09T16:10:24.253ZMay 09 16:10:24.223 INFO creating external link mgtriobfd_cr1_vn_vnic1
5562026-05-09T16:10:24.253ZMay 09 16:10:24.224 DEBG external link mgtriobfd_cr1_vn_vnic1@igb0 created
5572026-05-09T16:10:24.253ZMay 09 16:10:24.224 DEBG destroying external link mgtriobfd_cr2_vn_vnic1
5582026-05-09T16:10:24.253ZMay 09 16:10:24.224 INFO creating external link mgtriobfd_cr2_vn_vnic1
5592026-05-09T16:10:24.253ZMay 09 16:10:24.226 DEBG external link mgtriobfd_cr2_vn_vnic1@igb0 created
5602026-05-09T16:10:24.253ZMay 09 16:10:24.226 INFO creating nodes
5612026-05-09T16:10:24.253ZMay 09 16:10:24.226 INFO ox: launching node
5622026-05-09T16:10:24.253ZMay 09 16:10:24.228 INFO cr1: launching node
5632026-05-09T16:10:24.253ZMay 09 16:10:24.232 INFO cr2: launching node
5642026-05-09T16:10:24.278ZMay 09 16:10:24.244 INFO launched instance cr2 with pid 898 on port 36699
5652026-05-09T16:10:24.278ZMay 09 16:10:24.244 INFO cr2: instance ensure
5662026-05-09T16:10:24.278ZMay 09 16:10:24.244 INFO launched instance ox with pid 896 on port 40969
5672026-05-09T16:10:24.278ZMay 09 16:10:24.245 INFO ox: instance ensure
5682026-05-09T16:10:24.278ZMay 09 16:10:24.245 INFO launched instance cr1 with pid 897 on port 39294
5692026-05-09T16:10:24.278ZMay 09 16:10:24.245 INFO cr1: instance ensure
5702026-05-09T16:10:26.473ZMay 09 16:10:26.461 INFO cr1: instance ensure completed after 0 retries
5712026-05-09T16:10:26.473ZMay 09 16:10:26.461 INFO cr1: instance run
5722026-05-09T16:10:26.498ZMay 09 16:10:26.462 DEBG [sc] cr1: starting
5732026-05-09T16:10:26.498ZMay 09 16:10:26.462 DEBG [sc] cr1: connecting to [::1]:39294
5742026-05-09T16:10:26.498ZMay 09 16:10:26.462 DEBG [sc] cr1 waiting for prompt
5752026-05-09T16:10:26.498ZMay 09 16:10:26.473 INFO cr2: instance ensure completed after 0 retries
5762026-05-09T16:10:26.498ZMay 09 16:10:26.473 INFO cr2: instance run
5772026-05-09T16:10:26.498ZMay 09 16:10:26.473 DEBG [sc] cr2: starting
5782026-05-09T16:10:26.498ZMay 09 16:10:26.474 DEBG [sc] cr2: connecting to [::1]:36699
5792026-05-09T16:10:26.498ZMay 09 16:10:26.474 DEBG [sc] cr2 waiting for prompt
5802026-05-09T16:10:26.523ZMay 09 16:10:26.499 INFO ox: instance ensure completed after 0 retries
5812026-05-09T16:10:26.523ZMay 09 16:10:26.499 INFO ox: instance run
5822026-05-09T16:10:26.523ZMay 09 16:10:26.499 DEBG [sc] ox: starting
5832026-05-09T16:10:26.523ZMay 09 16:10:26.500 DEBG [sc] ox: connecting to [::1]:40969
5842026-05-09T16:10:26.523ZMay 09 16:10:26.500 DEBG [sc] ox waiting for prompt
5852026-05-09T16:10:43.598ZMay 09 16:10:43.586 DEBG [sc] cr1: logging in
5862026-05-09T16:10:44.014ZMay 09 16:10:44.002 INFO cr1: mounting /opt/cargo-bay
5872026-05-09T16:10:44.014ZMay 09 16:10:44.002 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5882026-05-09T16:10:44.038ZMay 09 16:10:44.024 DEBG [sc] cr1: executing command `cd`
5892026-05-09T16:10:44.063ZMay 09 16:10:44.035 INFO cr1: finished mounting /opt/cargo-bay
5902026-05-09T16:10:44.063ZMay 09 16:10:44.035 DEBG [sc] cr1: executing command `hostname cr1`
5912026-05-09T16:10:44.063ZMay 09 16:10:44.045 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
5922026-05-09T16:10:44.088ZMay 09 16:10:44.057 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
5932026-05-09T16:10:44.088ZMay 09 16:10:44.068 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
5942026-05-09T16:10:44.112ZMay 09 16:10:44.079 INFO cr1: logging out
5952026-05-09T16:10:46.155ZMay 09 16:10:46.143 INFO cr1: logged out
5962026-05-09T16:10:47.109ZMay 09 16:10:47.097 DEBG [sc] ox: logging in
5972026-05-09T16:10:47.291ZMay 09 16:10:47.279 INFO ox: mounting /opt/cargo-bay
5982026-05-09T16:10:47.291ZMay 09 16:10:47.279 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5992026-05-09T16:10:48.131ZMay 09 16:10:48.119 DEBG [sc] cr2: logging in
6002026-05-09T16:10:48.449ZMay 09 16:10:48.437 DEBG [sc] ox: executing command `cd`
6012026-05-09T16:10:48.474ZMay 09 16:10:48.447 INFO ox: finished mounting /opt/cargo-bay
6022026-05-09T16:10:48.474ZMay 09 16:10:48.447 DEBG [sc] ox: executing command `hostname ox`
6032026-05-09T16:10:48.474ZMay 09 16:10:48.458 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
6042026-05-09T16:10:48.498ZMay 09 16:10:48.470 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
6052026-05-09T16:10:48.498ZMay 09 16:10:48.481 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
6062026-05-09T16:10:48.523ZMay 09 16:10:48.492 INFO ox: logging out
6072026-05-09T16:10:48.556ZMay 09 16:10:48.544 INFO cr2: mounting /opt/cargo-bay
6082026-05-09T16:10:48.556ZMay 09 16:10:48.544 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
6092026-05-09T16:10:48.580ZMay 09 16:10:48.567 DEBG [sc] cr2: executing command `cd`
6102026-05-09T16:10:48.605ZMay 09 16:10:48.578 INFO cr2: finished mounting /opt/cargo-bay
6112026-05-09T16:10:48.605ZMay 09 16:10:48.578 DEBG [sc] cr2: executing command `hostname cr2`
6122026-05-09T16:10:48.605ZMay 09 16:10:48.589 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
6132026-05-09T16:10:48.629ZMay 09 16:10:48.599 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
6142026-05-09T16:10:48.629ZMay 09 16:10:48.608 INFO ox: logged out
6152026-05-09T16:10:48.630ZMay 09 16:10:48.610 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
6162026-05-09T16:10:48.654ZMay 09 16:10:48.621 INFO cr2: logging out
6172026-05-09T16:10:51.576ZMay 09 16:10:51.564 INFO cr2: logged out
6182026-05-09T16:10:51.601ZMay 09 16:10:51.564 DEBG [sc] ox: starting
6192026-05-09T16:10:51.601ZMay 09 16:10:51.564 DEBG [sc] ox: connecting to [::1]:40969
6202026-05-09T16:10:51.601ZMay 09 16:10:51.565 DEBG [sc] ox waiting for prompt
6212026-05-09T16:10:51.601ZMay 09 16:10:51.575 DEBG [sc] ox: logging in
6222026-05-09T16:10:51.676ZMay 09 16:10:51.664 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
6232026-05-09T16:10:58.227ZMay 09 16:10:58.215 DEBG [sc] ox: starting
6242026-05-09T16:10:58.227ZMay 09 16:10:58.215 DEBG [sc] ox: connecting to [::1]:40969
6252026-05-09T16:10:58.252ZMay 09 16:10:58.216 DEBG [sc] ox waiting for prompt
6262026-05-09T16:10:58.252ZMay 09 16:10:58.226 DEBG [sc] ox: logging in
6272026-05-09T16:10:58.326ZMay 09 16:10:58.315 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
6282026-05-09T16:10:58.414ZMay 09 16:10:58.403 DEBG [sc] ox: starting
6292026-05-09T16:10:58.414ZMay 09 16:10:58.403 DEBG [sc] ox: connecting to [::1]:40969
6302026-05-09T16:10:58.439ZMay 09 16:10:58.403 DEBG [sc] ox waiting for prompt
6312026-05-09T16:10:58.439ZMay 09 16:10:58.414 DEBG [sc] ox: logging in
6322026-05-09T16:10:58.502ZMay 09 16:10:58.491 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
6332026-05-09T16:10:58.568ZMay 09 16:10:58.556 INFO cr1: installing frr
6342026-05-09T16:10:58.568ZMay 09 16:10:58.556 INFO waiting for ceos to initialize
6352026-05-09T16:10:58.568ZMay 09 16:10:58.556 INFO ox: setting up npuvm
6362026-05-09T16:10:58.592ZMay 09 16:10:58.556 DEBG [sc] cr1: starting
6372026-05-09T16:10:58.592ZMay 09 16:10:58.556 DEBG [sc] cr1: connecting to [::1]:39294
6382026-05-09T16:10:58.592ZMay 09 16:10:58.556 DEBG [sc] cr2: starting
6392026-05-09T16:10:58.592ZMay 09 16:10:58.556 DEBG [sc] cr2: connecting to [::1]:36699
6402026-05-09T16:10:58.592ZMay 09 16:10:58.556 DEBG [sc] ox: starting
6412026-05-09T16:10:58.592ZMay 09 16:10:58.556 DEBG [sc] ox: connecting to [::1]:40969
6422026-05-09T16:10:58.592ZMay 09 16:10:58.557 DEBG [sc] ox waiting for prompt
6432026-05-09T16:10:58.593ZMay 09 16:10:58.557 DEBG [sc] cr1 waiting for prompt
6442026-05-09T16:10:58.593ZMay 09 16:10:58.557 DEBG [sc] cr2 waiting for prompt
6452026-05-09T16:10:58.593ZMay 09 16:10:58.567 DEBG [sc] ox: logging in
6462026-05-09T16:10:58.593ZMay 09 16:10:58.568 DEBG [sc] cr1: logging in
6472026-05-09T16:10:58.593ZMay 09 16:10:58.568 DEBG [sc] cr2: logging in
6482026-05-09T16:10:58.657ZMay 09 16:10:58.645 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
6492026-05-09T16:10:58.724ZMay 09 16:10:58.712 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6502026-05-09T16:10:58.924ZMay 09 16:10:58.912 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
6512026-05-09T16:11:00.985ZMay 09 16:11:00.973 INFO cr2: executing eos script show version
6522026-05-09T16:11:00.985ZMay 09 16:11:00.973 DEBG [sc] cr2: starting
6532026-05-09T16:11:00.985ZMay 09 16:11:00.973 DEBG [sc] cr2: connecting to [::1]:36699
6542026-05-09T16:11:01.010ZMay 09 16:11:00.974 DEBG [sc] cr2 waiting for prompt
6552026-05-09T16:11:01.010ZMay 09 16:11:00.984 DEBG [sc] cr2: logging in
6562026-05-09T16:11:01.139ZMay 09 16:11:01.128 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6572026-05-09T16:11:04.054ZMay 09 16:11:04.042 DEBG [sc] ox: starting
6582026-05-09T16:11:04.054ZMay 09 16:11:04.042 DEBG [sc] ox: connecting to [::1]:40969
6592026-05-09T16:11:04.078ZMay 09 16:11:04.042 DEBG [sc] ox waiting for prompt
6602026-05-09T16:11:04.078ZMay 09 16:11:04.052 DEBG [sc] ox: logging in
6612026-05-09T16:11:04.141ZMay 09 16:11:04.129 DEBG [sc] ox: executing command `chmod +x npuvm`
6622026-05-09T16:11:04.207ZMay 09 16:11:04.196 DEBG [sc] ox: starting
6632026-05-09T16:11:04.207ZMay 09 16:11:04.196 DEBG [sc] ox: connecting to [::1]:40969
6642026-05-09T16:11:04.232ZMay 09 16:11:04.196 DEBG [sc] ox waiting for prompt
6652026-05-09T16:11:04.232ZMay 09 16:11:04.206 DEBG [sc] ox: logging in
6662026-05-09T16:11:04.307ZMay 09 16:11:04.295 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
6672026-05-09T16:11:08.239ZMay 09 16:11:08.227 INFO cr1: enabling frr daemon bfdd
6682026-05-09T16:11:08.240ZMay 09 16:11:08.227 DEBG [sc] cr1: starting
6692026-05-09T16:11:08.264ZMay 09 16:11:08.227 DEBG [sc] cr1: connecting to [::1]:39294
6702026-05-09T16:11:08.264ZMay 09 16:11:08.228 DEBG [sc] cr1 waiting for prompt
6712026-05-09T16:11:08.264ZMay 09 16:11:08.238 DEBG [sc] cr1: logging in
6722026-05-09T16:11:08.383ZMay 09 16:11:08.371 DEBG [sc] cr1: executing command `sed -i 's/bfdd=no/bfdd=yes/g' /etc/frr/daemons`
6732026-05-09T16:11:09.196ZMay 09 16:11:09.184 DEBG [sc] cr2: starting
6742026-05-09T16:11:09.196ZMay 09 16:11:09.184 DEBG [sc] cr2: connecting to [::1]:36699
6752026-05-09T16:11:09.221ZMay 09 16:11:09.185 DEBG [sc] cr2 waiting for prompt
6762026-05-09T16:11:09.221ZMay 09 16:11:09.195 DEBG [sc] cr2: logging in
6772026-05-09T16:11:09.361ZMay 09 16:11:09.349 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6782026-05-09T16:11:10.460ZMay 09 16:11:10.448 DEBG [sc] cr1: starting
6792026-05-09T16:11:10.460ZMay 09 16:11:10.448 DEBG [sc] cr1: connecting to [::1]:39294
6802026-05-09T16:11:10.484ZMay 09 16:11:10.448 DEBG [sc] cr1 waiting for prompt
6812026-05-09T16:11:10.484ZMay 09 16:11:10.458 DEBG [sc] cr1: logging in
6822026-05-09T16:11:10.602ZMay 09 16:11:10.590 DEBG [sc] cr1: executing command `systemctl restart frr`
6832026-05-09T16:11:11.437ZMay 09 16:11:11.425 INFO cr2: executing eos script show version
6842026-05-09T16:11:11.462ZMay 09 16:11:11.426 DEBG [sc] cr2: starting
6852026-05-09T16:11:11.462ZMay 09 16:11:11.426 DEBG [sc] cr2: connecting to [::1]:36699
6862026-05-09T16:11:11.462ZMay 09 16:11:11.426 DEBG [sc] cr2 waiting for prompt
6872026-05-09T16:11:11.462ZMay 09 16:11:11.436 DEBG [sc] cr2: logging in
6882026-05-09T16:11:11.591ZMay 09 16:11:11.579 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6892026-05-09T16:11:13.931ZMay 09 16:11:13.919 DEBG [sc] cr2: starting
6902026-05-09T16:11:13.931ZMay 09 16:11:13.919 DEBG [sc] cr2: connecting to [::1]:36699
6912026-05-09T16:11:13.956ZMay 09 16:11:13.919 DEBG [sc] cr2 waiting for prompt
6922026-05-09T16:11:13.956ZMay 09 16:11:13.930 DEBG [sc] cr2: logging in
6932026-05-09T16:11:14.107ZMay 09 16:11:14.095 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6942026-05-09T16:11:16.245ZMay 09 16:11:16.233 INFO cr2: executing eos script show version
6952026-05-09T16:11:16.245ZMay 09 16:11:16.233 DEBG [sc] cr2: starting
6962026-05-09T16:11:16.245ZMay 09 16:11:16.233 DEBG [sc] cr2: connecting to [::1]:36699
6972026-05-09T16:11:16.270ZMay 09 16:11:16.233 DEBG [sc] cr2 waiting for prompt
6982026-05-09T16:11:16.270ZMay 09 16:11:16.244 DEBG [sc] cr2: logging in
6992026-05-09T16:11:16.410ZMay 09 16:11:16.398 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
7002026-05-09T16:11:18.173ZMay 09 16:11:18.161 INFO cr1: executing frr script
7012026-05-09T16:11:18.173Z configure
7022026-05-09T16:11:18.173Z interface enp0s8
7032026-05-09T16:11:18.173Z ip address 10.0.0.2/24
7042026-05-09T16:11:18.173Z ipv6 address fd00:1::2/64
7052026-05-09T16:11:18.173Z no shutdown
7062026-05-09T16:11:18.173Z exit
7072026-05-09T16:11:18.173Z bfd
7082026-05-09T16:11:18.173Z peer 10.0.0.1 local-address 10.0.0.2
7092026-05-09T16:11:18.173Z detect-multiplier 3
7102026-05-09T16:11:18.173Z receive-interval 300
7112026-05-09T16:11:18.173Z transmit-interval 300
7122026-05-09T16:11:18.173Z no shutdown
7132026-05-09T16:11:18.173Z exit
7142026-05-09T16:11:18.173Z peer fd00:1::1 local-address fd00:1::2
7152026-05-09T16:11:18.173Z detect-multiplier 3
7162026-05-09T16:11:18.173Z receive-interval 300
7172026-05-09T16:11:18.173Z transmit-interval 300
7182026-05-09T16:11:18.173Z no shutdown
7192026-05-09T16:11:18.173Z exit
7202026-05-09T16:11:18.173Z exit
7212026-05-09T16:11:18.173Z
7222026-05-09T16:11:18.198ZMay 09 16:11:18.161 DEBG [sc] cr1: starting
7232026-05-09T16:11:18.198ZMay 09 16:11:18.161 DEBG [sc] cr1: connecting to [::1]:39294
7242026-05-09T16:11:18.198ZMay 09 16:11:18.162 DEBG [sc] cr1 waiting for prompt
7252026-05-09T16:11:18.198ZMay 09 16:11:18.173 DEBG [sc] cr1: logging in
7262026-05-09T16:11:18.338ZMay 09 16:11:18.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 ' '`
7272026-05-09T16:11:18.773ZMay 09 16:11:18.761 DEBG [sc] cr2: starting
7282026-05-09T16:11:18.773ZMay 09 16:11:18.761 DEBG [sc] cr2: connecting to [::1]:36699
7292026-05-09T16:11:18.798ZMay 09 16:11:18.762 DEBG [sc] cr2 waiting for prompt
7302026-05-09T16:11:18.798ZMay 09 16:11:18.772 DEBG [sc] cr2: logging in
7312026-05-09T16:11:18.894ZMay 09 16:11:18.882 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
7322026-05-09T16:11:21.014ZMay 09 16:11:21.002 INFO cr2: executing eos script show version
7332026-05-09T16:11:21.014ZMay 09 16:11:21.002 DEBG [sc] cr2: starting
7342026-05-09T16:11:21.014ZMay 09 16:11:21.002 DEBG [sc] cr2: connecting to [::1]:36699
7352026-05-09T16:11:21.038ZMay 09 16:11:21.003 DEBG [sc] cr2 waiting for prompt
7362026-05-09T16:11:21.038ZMay 09 16:11:21.013 DEBG [sc] cr2: logging in
7372026-05-09T16:11:21.168ZMay 09 16:11:21.156 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
7382026-05-09T16:11:23.472ZMay 09 16:11:23.461 INFO cr2: executing eos script
7392026-05-09T16:11:23.473Z enable
7402026-05-09T16:11:23.473Z configure
7412026-05-09T16:11:23.473Z ip routing
7422026-05-09T16:11:23.473Z ipv6 unicast-routing
7432026-05-09T16:11:23.473Z interface Ethernet1
7442026-05-09T16:11:23.473Z no switchport
7452026-05-09T16:11:23.473Z ip address 10.0.1.2/24
7462026-05-09T16:11:23.473Z ipv6 enable
7472026-05-09T16:11:23.473Z ipv6 address fd00:2::2/64
7482026-05-09T16:11:23.473Z bfd interval 300 min-rx 300 multiplier 3
7492026-05-09T16:11:23.473Z exit
7502026-05-09T16:11:23.473Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7512026-05-09T16:11:23.473Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7522026-05-09T16:11:23.473Z exit
7532026-05-09T16:11:23.473Z
7542026-05-09T16:11:23.473ZMay 09 16:11:23.461 DEBG [sc] cr2: starting
7552026-05-09T16:11:23.473ZMay 09 16:11:23.461 DEBG [sc] cr2: connecting to [::1]:36699
7562026-05-09T16:11:23.498ZMay 09 16:11:23.461 DEBG [sc] cr2 waiting for prompt
7572026-05-09T16:11:23.498ZMay 09 16:11:23.471 DEBG [sc] cr2: logging in
7582026-05-09T16:11:23.628ZMay 09 16:11:23.616 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
7592026-05-09T16:11:23.628Z enable
7602026-05-09T16:11:23.628Z configure
7612026-05-09T16:11:23.628Z ip routing
7622026-05-09T16:11:23.628Z ipv6 unicast-routing
7632026-05-09T16:11:23.628Z interface Ethernet1
7642026-05-09T16:11:23.628Z no switchport
7652026-05-09T16:11:23.628Z ip address 10.0.1.2/24
7662026-05-09T16:11:23.628Z ipv6 enable
7672026-05-09T16:11:23.628Z ipv6 address fd00:2::2/64
7682026-05-09T16:11:23.628Z bfd interval 300 min-rx 300 multiplier 3
7692026-05-09T16:11:23.628Z exit
7702026-05-09T16:11:23.628Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7712026-05-09T16:11:23.628Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7722026-05-09T16:11:23.628Z exit
7732026-05-09T16:11:23.628Z '`
7742026-05-09T16:12:52.020ZMay 09 16:12:52.008 DEBG [sc] ox: starting
7752026-05-09T16:12:52.020ZMay 09 16:12:52.008 DEBG [sc] ox: connecting to [::1]:40969
7762026-05-09T16:12:52.045ZMay 09 16:12:52.008 DEBG [sc] ox waiting for prompt
7772026-05-09T16:12:52.045ZMay 09 16:12:52.019 DEBG [sc] ox: logging in
7782026-05-09T16:12:52.107ZMay 09 16:12:52.095 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
7792026-05-09T16:12:52.394ZMay 09 16:12:52.382 DEBG [sc] ox: starting
7802026-05-09T16:12:52.394ZMay 09 16:12:52.382 DEBG [sc] ox: connecting to [::1]:40969
7812026-05-09T16:12:52.418ZMay 09 16:12:52.382 DEBG [sc] ox waiting for prompt
7822026-05-09T16:12:52.418ZMay 09 16:12:52.394 DEBG [sc] ox: logging in
7832026-05-09T16:12:52.482ZMay 09 16:12:52.471 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7842026-05-09T16:12:53.506ZMay 09 16:12:53.494 DEBG [sc] ox: starting
7852026-05-09T16:12:53.506ZMay 09 16:12:53.494 DEBG [sc] ox: connecting to [::1]:40969
7862026-05-09T16:12:53.530ZMay 09 16:12:53.495 DEBG [sc] ox waiting for prompt
7872026-05-09T16:12:53.530ZMay 09 16:12:53.495 DEBG [sc] ox: logging in
7882026-05-09T16:12:53.584ZMay 09 16:12:53.572 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7892026-05-09T16:12:53.640ZMay 09 16:12:53.628 DEBG [sc] ox: starting
7902026-05-09T16:12:53.640ZMay 09 16:12:53.628 DEBG [sc] ox: connecting to [::1]:40969
7912026-05-09T16:12:53.665ZMay 09 16:12:53.629 DEBG [sc] ox waiting for prompt
7922026-05-09T16:12:53.665ZMay 09 16:12:53.639 DEBG [sc] ox: logging in
7932026-05-09T16:12:53.728ZMay 09 16:12:53.716 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7942026-05-09T16:12:54.117ZMay 09 16:12:54.104 DEBG [sc] ox: starting
7952026-05-09T16:12:54.117ZMay 09 16:12:54.104 DEBG [sc] ox: connecting to [::1]:40969
7962026-05-09T16:12:54.141ZMay 09 16:12:54.105 DEBG [sc] ox waiting for prompt
7972026-05-09T16:12:54.141ZMay 09 16:12:54.116 DEBG [sc] ox: logging in
7982026-05-09T16:12:54.205ZMay 09 16:12:54.192 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
7992026-05-09T16:12:54.271ZMay 09 16:12:54.259 DEBG [sc] ox: starting
8002026-05-09T16:12:54.271ZMay 09 16:12:54.259 DEBG [sc] ox: connecting to [::1]:40969
8012026-05-09T16:12:54.295ZMay 09 16:12:54.259 DEBG [sc] ox waiting for prompt
8022026-05-09T16:12:54.295ZMay 09 16:12:54.270 DEBG [sc] ox: logging in
8032026-05-09T16:12:54.369ZMay 09 16:12:54.358 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
8042026-05-09T16:12:54.436ZMay 09 16:12:54.424 DEBG [sc] ox: starting
8052026-05-09T16:12:54.436ZMay 09 16:12:54.424 DEBG [sc] ox: connecting to [::1]:40969
8062026-05-09T16:12:54.460ZMay 09 16:12:54.425 DEBG [sc] ox waiting for prompt
8072026-05-09T16:12:54.460ZMay 09 16:12:54.435 DEBG [sc] ox: logging in
8082026-05-09T16:12:54.523ZMay 09 16:12:54.512 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.0.1/24 tfportqsfp0_0/v4`
8092026-05-09T16:12:55.157ZMay 09 16:12:55.145 DEBG [sc] ox: starting
8102026-05-09T16:12:55.157ZMay 09 16:12:55.145 DEBG [sc] ox: connecting to [::1]:40969
8112026-05-09T16:12:55.182ZMay 09 16:12:55.146 DEBG [sc] ox waiting for prompt
8122026-05-09T16:12:55.182ZMay 09 16:12:55.156 DEBG [sc] ox: logging in
8132026-05-09T16:12:55.245ZMay 09 16:12:55.233 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v4 -p -o addr`
8142026-05-09T16:12:55.311ZMay 09 16:12:55.299 DEBG [sc] ox: starting
8152026-05-09T16:12:55.311ZMay 09 16:12:55.299 DEBG [sc] ox: connecting to [::1]:40969
8162026-05-09T16:12:55.336ZMay 09 16:12:55.300 DEBG [sc] ox waiting for prompt
8172026-05-09T16:12:55.336ZMay 09 16:12:55.310 DEBG [sc] ox: logging in
8182026-05-09T16:12:55.400ZMay 09 16:12:55.389 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:1::1/64 tfportqsfp0_0/v6`
8192026-05-09T16:12:55.914ZMay 09 16:12:55.902 DEBG [sc] ox: starting
8202026-05-09T16:12:55.914ZMay 09 16:12:55.902 DEBG [sc] ox: connecting to [::1]:40969
8212026-05-09T16:12:55.939ZMay 09 16:12:55.903 DEBG [sc] ox waiting for prompt
8222026-05-09T16:12:55.939ZMay 09 16:12:55.913 DEBG [sc] ox: logging in
8232026-05-09T16:12:56.002ZMay 09 16:12:55.990 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v6 -p -o addr`
8242026-05-09T16:12:56.057ZMay 09 16:12:56.045 DEBG [sc] ox: starting
8252026-05-09T16:12:56.057ZMay 09 16:12:56.045 DEBG [sc] ox: connecting to [::1]:40969
8262026-05-09T16:12:56.081ZMay 09 16:12:56.045 DEBG [sc] ox waiting for prompt
8272026-05-09T16:12:56.081ZMay 09 16:12:56.056 DEBG [sc] ox: logging in
8282026-05-09T16:12:56.145ZMay 09 16:12:56.133 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
8292026-05-09T16:12:56.201ZMay 09 16:12:56.188 DEBG [sc] ox: starting
8302026-05-09T16:12:56.201ZMay 09 16:12:56.188 DEBG [sc] ox: connecting to [::1]:40969
8312026-05-09T16:12:56.226ZMay 09 16:12:56.189 DEBG [sc] ox waiting for prompt
8322026-05-09T16:12:56.226ZMay 09 16:12:56.199 DEBG [sc] ox: logging in
8332026-05-09T16:12:56.288ZMay 09 16:12:56.276 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
8342026-05-09T16:12:56.343ZMay 09 16:12:56.331 DEBG [sc] ox: starting
8352026-05-09T16:12:56.343ZMay 09 16:12:56.331 DEBG [sc] ox: connecting to [::1]:40969
8362026-05-09T16:12:56.367ZMay 09 16:12:56.332 DEBG [sc] ox waiting for prompt
8372026-05-09T16:12:56.368ZMay 09 16:12:56.342 DEBG [sc] ox: logging in
8382026-05-09T16:12:56.431ZMay 09 16:12:56.419 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.1.1/24 tfportqsfp1_0/v4`
8392026-05-09T16:12:57.094ZMay 09 16:12:57.081 DEBG [sc] ox: starting
8402026-05-09T16:12:57.094ZMay 09 16:12:57.081 DEBG [sc] ox: connecting to [::1]:40969
8412026-05-09T16:12:57.119ZMay 09 16:12:57.082 DEBG [sc] ox waiting for prompt
8422026-05-09T16:12:57.119ZMay 09 16:12:57.092 DEBG [sc] ox: logging in
8432026-05-09T16:12:57.181ZMay 09 16:12:57.169 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v4 -p -o addr`
8442026-05-09T16:12:57.236ZMay 09 16:12:57.224 DEBG [sc] ox: starting
8452026-05-09T16:12:57.236ZMay 09 16:12:57.224 DEBG [sc] ox: connecting to [::1]:40969
8462026-05-09T16:12:57.261ZMay 09 16:12:57.225 DEBG [sc] ox waiting for prompt
8472026-05-09T16:12:57.261ZMay 09 16:12:57.235 DEBG [sc] ox: logging in
8482026-05-09T16:12:57.324ZMay 09 16:12:57.312 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:2::1/64 tfportqsfp1_0/v6`
8492026-05-09T16:12:57.836ZMay 09 16:12:57.824 DEBG [sc] ox: starting
8502026-05-09T16:12:57.836ZMay 09 16:12:57.824 DEBG [sc] ox: connecting to [::1]:40969
8512026-05-09T16:12:57.861ZMay 09 16:12:57.825 DEBG [sc] ox waiting for prompt
8522026-05-09T16:12:57.861ZMay 09 16:12:57.835 DEBG [sc] ox: logging in
8532026-05-09T16:12:57.923ZMay 09 16:12:57.912 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v6 -p -o addr`
8542026-05-09T16:12:57.979ZMay 09 16:12:57.967 DEBG [sc] ox: starting
8552026-05-09T16:12:57.979ZMay 09 16:12:57.967 DEBG [sc] ox: connecting to [::1]:40969
8562026-05-09T16:12:58.004ZMay 09 16:12:57.968 DEBG [sc] ox waiting for prompt
8572026-05-09T16:12:58.004ZMay 09 16:12:57.978 DEBG [sc] ox: logging in
8582026-05-09T16:12:58.067ZMay 09 16:12:58.055 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
8592026-05-09T16:12:58.122ZMay 09 16:12:58.110 DEBG [sc] ox: starting
8602026-05-09T16:12:58.122ZMay 09 16:12:58.110 DEBG [sc] ox: connecting to [::1]:40969
8612026-05-09T16:12:58.147ZMay 09 16:12:58.111 DEBG [sc] ox waiting for prompt
8622026-05-09T16:12:58.147ZMay 09 16:12:58.122 DEBG [sc] ox: logging in
8632026-05-09T16:12:58.212ZMay 09 16:12:58.200 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
8642026-05-09T16:12:58.282ZMay 09 16:12:58.270 INFO installing static v4 route 192.168.100.0/24
8652026-05-09T16:12:58.307ZMay 09 16:12:58.271 INFO installing static v6 route fd01::/64
8662026-05-09T16:12:58.307ZMay 09 16:12:58.272 INFO adding BFD peers for cr1 and cr2 (dual-stack)
8672026-05-09T16:12:58.307ZMay 09 16:12:58.275 INFO phase 1: both peers up
8682026-05-09T16:12:59.292ZMay 09 16:12:59.280 INFO cr1: executing frr script show bfd peers json
8692026-05-09T16:12:59.292ZMay 09 16:12:59.281 DEBG [sc] cr1: starting
8702026-05-09T16:12:59.292ZMay 09 16:12:59.281 DEBG [sc] cr1: connecting to [::1]:39294
8712026-05-09T16:12:59.317ZMay 09 16:12:59.281 DEBG [sc] cr1 waiting for prompt
8722026-05-09T16:12:59.317ZMay 09 16:12:59.292 DEBG [sc] cr1: logging in
8732026-05-09T16:12:59.673ZMay 09 16:12:59.661 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8742026-05-09T16:13:01.815ZMay 09 16:13:01.803 INFO cr1: executing frr script show bfd peers json
8752026-05-09T16:13:01.840ZMay 09 16:13:01.803 DEBG [sc] cr1: starting
8762026-05-09T16:13:01.840ZMay 09 16:13:01.803 DEBG [sc] cr1: connecting to [::1]:39294
8772026-05-09T16:13:01.840ZMay 09 16:13:01.804 DEBG [sc] cr1 waiting for prompt
8782026-05-09T16:13:01.840ZMay 09 16:13:01.813 DEBG [sc] cr1: logging in
8792026-05-09T16:13:01.979ZMay 09 16:13:01.967 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8802026-05-09T16:13:04.117ZMay 09 16:13:04.105 INFO cr2: executing eos script show bfd peers | json
8812026-05-09T16:13:04.117ZMay 09 16:13:04.105 DEBG [sc] cr2: starting
8822026-05-09T16:13:04.117ZMay 09 16:13:04.105 DEBG [sc] cr2: connecting to [::1]:36699
8832026-05-09T16:13:04.141ZMay 09 16:13:04.106 DEBG [sc] cr2 waiting for prompt
8842026-05-09T16:13:04.141ZMay 09 16:13:04.117 DEBG [sc] cr2: logging in
8852026-05-09T16:13:04.452ZMay 09 16:13:04.440 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8862026-05-09T16:13:06.805ZMay 09 16:13:06.793 INFO cr2: executing eos script show bfd peers | json
8872026-05-09T16:13:06.805ZMay 09 16:13:06.793 DEBG [sc] cr2: starting
8882026-05-09T16:13:06.805ZMay 09 16:13:06.793 DEBG [sc] cr2: connecting to [::1]:36699
8892026-05-09T16:13:06.830ZMay 09 16:13:06.794 DEBG [sc] cr2 waiting for prompt
8902026-05-09T16:13:06.830ZMay 09 16:13:06.803 DEBG [sc] cr2: logging in
8912026-05-09T16:13:06.980ZMay 09 16:13:06.968 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8922026-05-09T16:13:09.332ZMay 09 16:13:09.320 INFO phase 2: pause bfdd on cr1
8932026-05-09T16:13:09.332ZMay 09 16:13:09.320 INFO cr1: pausing frr bfdd
8942026-05-09T16:13:09.333ZMay 09 16:13:09.320 DEBG [sc] cr1: starting
8952026-05-09T16:13:09.333ZMay 09 16:13:09.320 DEBG [sc] cr1: connecting to [::1]:39294
8962026-05-09T16:13:09.357ZMay 09 16:13:09.321 DEBG [sc] cr1 waiting for prompt
8972026-05-09T16:13:09.357ZMay 09 16:13:09.333 DEBG [sc] cr1: logging in
8982026-05-09T16:13:09.516ZMay 09 16:13:09.488 DEBG [sc] cr1: executing command `pkill -STOP bfdd`
8992026-05-09T16:13:11.585ZMay 09 16:13:11.573 INFO cr2: executing eos script show bfd peers | json
9002026-05-09T16:13:11.585ZMay 09 16:13:11.573 DEBG [sc] cr2: starting
9012026-05-09T16:13:11.609ZMay 09 16:13:11.573 DEBG [sc] cr2: connecting to [::1]:36699
9022026-05-09T16:13:11.609ZMay 09 16:13:11.574 DEBG [sc] cr2 waiting for prompt
9032026-05-09T16:13:11.609ZMay 09 16:13:11.585 DEBG [sc] cr2: logging in
9042026-05-09T16:13:11.730ZMay 09 16:13:11.718 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9052026-05-09T16:13:14.094ZMay 09 16:13:14.082 INFO cr2: executing eos script show bfd peers | json
9062026-05-09T16:13:14.094ZMay 09 16:13:14.082 DEBG [sc] cr2: starting
9072026-05-09T16:13:14.094ZMay 09 16:13:14.082 DEBG [sc] cr2: connecting to [::1]:36699
9082026-05-09T16:13:14.119ZMay 09 16:13:14.083 DEBG [sc] cr2 waiting for prompt
9092026-05-09T16:13:14.119ZMay 09 16:13:14.092 DEBG [sc] cr2: logging in
9102026-05-09T16:13:14.248ZMay 09 16:13:14.236 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9112026-05-09T16:13:16.596ZMay 09 16:13:16.585 INFO phase 3: pause ceos on cr2
9122026-05-09T16:13:16.596ZMay 09 16:13:16.585 INFO cr2: pausing ceos
9132026-05-09T16:13:16.596ZMay 09 16:13:16.585 DEBG [sc] cr2: starting
9142026-05-09T16:13:16.596ZMay 09 16:13:16.585 DEBG [sc] cr2: connecting to [::1]:36699
9152026-05-09T16:13:16.621ZMay 09 16:13:16.585 DEBG [sc] cr2 waiting for prompt
9162026-05-09T16:13:16.621ZMay 09 16:13:16.594 DEBG [sc] cr2: logging in
9172026-05-09T16:13:16.750ZMay 09 16:13:16.738 DEBG [sc] cr2: executing command `docker pause ceos`
9182026-05-09T16:13:18.865ZMay 09 16:13:18.853 INFO phase 4: resume bfdd on cr1
9192026-05-09T16:13:18.865ZMay 09 16:13:18.853 INFO cr1: resuming frr bfdd
9202026-05-09T16:13:18.865ZMay 09 16:13:18.853 DEBG [sc] cr1: starting
9212026-05-09T16:13:18.865ZMay 09 16:13:18.853 DEBG [sc] cr1: connecting to [::1]:39294
9222026-05-09T16:13:18.890ZMay 09 16:13:18.853 DEBG [sc] cr1 waiting for prompt
9232026-05-09T16:13:18.890ZMay 09 16:13:18.865 DEBG [sc] cr1: logging in
9242026-05-09T16:13:18.997ZMay 09 16:13:18.985 DEBG [sc] cr1: executing command `pkill -CONT bfdd`
9252026-05-09T16:13:21.085ZMay 09 16:13:21.073 INFO cr1: executing frr script show bfd peers json
9262026-05-09T16:13:21.085ZMay 09 16:13:21.073 DEBG [sc] cr1: starting
9272026-05-09T16:13:21.109ZMay 09 16:13:21.073 DEBG [sc] cr1: connecting to [::1]:39294
9282026-05-09T16:13:21.109ZMay 09 16:13:21.073 DEBG [sc] cr1 waiting for prompt
9292026-05-09T16:13:21.109ZMay 09 16:13:21.082 DEBG [sc] cr1: logging in
9302026-05-09T16:13:21.237ZMay 09 16:13:21.226 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9312026-05-09T16:13:23.374ZMay 09 16:13:23.363 INFO cr1: executing frr script show bfd peers json
9322026-05-09T16:13:23.375ZMay 09 16:13:23.363 DEBG [sc] cr1: starting
9332026-05-09T16:13:23.375ZMay 09 16:13:23.363 DEBG [sc] cr1: connecting to [::1]:39294
9342026-05-09T16:13:23.399ZMay 09 16:13:23.363 DEBG [sc] cr1 waiting for prompt
9352026-05-09T16:13:23.399ZMay 09 16:13:23.374 DEBG [sc] cr1: logging in
9362026-05-09T16:13:23.529ZMay 09 16:13:23.517 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9372026-05-09T16:13:25.688ZMay 09 16:13:25.676 INFO phase 5: unpause ceos on cr2
9382026-05-09T16:13:25.688ZMay 09 16:13:25.676 INFO cr2: unpausing ceos
9392026-05-09T16:13:25.688ZMay 09 16:13:25.676 DEBG [sc] cr2: starting
9402026-05-09T16:13:25.688ZMay 09 16:13:25.676 DEBG [sc] cr2: connecting to [::1]:36699
9412026-05-09T16:13:25.712ZMay 09 16:13:25.676 DEBG [sc] cr2 waiting for prompt
9422026-05-09T16:13:25.712ZMay 09 16:13:25.687 DEBG [sc] cr2: logging in
9432026-05-09T16:13:25.831ZMay 09 16:13:25.819 DEBG [sc] cr2: executing command `docker unpause ceos`
9442026-05-09T16:13:27.941ZMay 09 16:13:27.929 INFO cr1: executing frr script show bfd peers json
9452026-05-09T16:13:27.941ZMay 09 16:13:27.929 DEBG [sc] cr1: starting
9462026-05-09T16:13:27.941ZMay 09 16:13:27.929 DEBG [sc] cr1: connecting to [::1]:39294
9472026-05-09T16:13:27.966ZMay 09 16:13:27.929 DEBG [sc] cr1 waiting for prompt
9482026-05-09T16:13:27.966ZMay 09 16:13:27.940 DEBG [sc] cr1: logging in
9492026-05-09T16:13:28.084ZMay 09 16:13:28.072 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9502026-05-09T16:13:30.224ZMay 09 16:13:30.212 INFO cr1: executing frr script show bfd peers json
9512026-05-09T16:13:30.248ZMay 09 16:13:30.212 DEBG [sc] cr1: starting
9522026-05-09T16:13:30.248ZMay 09 16:13:30.212 DEBG [sc] cr1: connecting to [::1]:39294
9532026-05-09T16:13:30.249ZMay 09 16:13:30.213 DEBG [sc] cr1 waiting for prompt
9542026-05-09T16:13:30.249ZMay 09 16:13:30.223 DEBG [sc] cr1: logging in
9552026-05-09T16:13:30.357ZMay 09 16:13:30.345 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9562026-05-09T16:13:32.506ZMay 09 16:13:32.495 INFO cr2: executing eos script show bfd peers | json
9572026-05-09T16:13:32.531ZMay 09 16:13:32.495 DEBG [sc] cr2: starting
9582026-05-09T16:13:32.531ZMay 09 16:13:32.495 DEBG [sc] cr2: connecting to [::1]:36699
9592026-05-09T16:13:32.531ZMay 09 16:13:32.496 DEBG [sc] cr2 waiting for prompt
9602026-05-09T16:13:32.531ZMay 09 16:13:32.507 DEBG [sc] cr2: logging in
9612026-05-09T16:13:32.684ZMay 09 16:13:32.672 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9622026-05-09T16:13:35.040ZMay 09 16:13:35.028 INFO cr2: executing eos script show bfd peers | json
9632026-05-09T16:13:35.040ZMay 09 16:13:35.028 DEBG [sc] cr2: starting
9642026-05-09T16:13:35.040ZMay 09 16:13:35.028 DEBG [sc] cr2: connecting to [::1]:36699
9652026-05-09T16:13:35.065ZMay 09 16:13:35.029 DEBG [sc] cr2 waiting for prompt
9662026-05-09T16:13:35.065ZMay 09 16:13:35.038 DEBG [sc] cr2: logging in
9672026-05-09T16:13:35.183ZMay 09 16:13:35.171 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9682026-05-09T16:13:37.516ZMay 09 16:13:37.503 INFO trio bfd static routing test passed 🎉
9692026-05-09T16:13:37.516ZMay 09 16:13:37.503 INFO destroying runner for deployment mgtriobfd
9702026-05-09T16:13:37.516ZMay 09 16:13:37.503 INFO destroying deployment mgtriobfd
9712026-05-09T16:13:37.540ZMay 09 16:13:37.503 INFO destroying nodes
9722026-05-09T16:13:37.634ZMay 09 16:13:37.622 INFO destroying links
9732026-05-09T16:13:37.634ZMay 09 16:13:37.622 INFO destroying link mgtriobfd_ox_sn_vnic0
9742026-05-09T16:13:37.658ZMay 09 16:13:37.624 INFO destroying link mgtriobfd_ox_sn_sim0
9752026-05-09T16:13:37.658ZMay 09 16:13:37.625 INFO destroying link mgtriobfd_cr1_vn_vnic0
9762026-05-09T16:13:38.639ZMay 09 16:13:38.627 INFO destroying link mgtriobfd_cr1_vn_sim0
9772026-05-09T16:13:38.663ZMay 09 16:13:38.628 INFO destroying link mgtriobfd_ox_sn_vnic1
9782026-05-09T16:13:38.663ZMay 09 16:13:38.629 INFO destroying link mgtriobfd_ox_sn_sim1
9792026-05-09T16:13:38.663ZMay 09 16:13:38.630 INFO destroying link mgtriobfd_cr2_vn_vnic0
9802026-05-09T16:13:38.663ZMay 09 16:13:38.631 INFO destroying link mgtriobfd_cr2_vn_sim0
9812026-05-09T16:13:38.663ZMay 09 16:13:38.632 INFO destroying external links
9822026-05-09T16:13:38.663ZMay 09 16:13:38.632 INFO destroying external link mgtriobfd_ox_vn_vnic2
9832026-05-09T16:13:38.663ZMay 09 16:13:38.633 INFO destroying external link mgtriobfd_cr1_vn_vnic1
9842026-05-09T16:13:38.663ZMay 09 16:13:38.634 INFO destroying external link mgtriobfd_cr2_vn_vnic1
9852026-05-09T16:13:38.663ZMay 09 16:13:38.636 INFO destroying images
9862026-05-09T16:13:39.126ZMay 09 16:13:39.114 INFO destroying workspace at .falcon
9872026-05-09T16:13:39.151Zprocess exited: duration 700157 ms, exit code 0
 
9882026-05-09T16:13:39.203Zfound 0 output files