01KQ13DG056X3RPX93Z2PMCEK7: falcon

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

Buildomat Job: 01KQ13DNGTT011GYMMY09Q72BR

Tags:

Output:

SEQ GLOBAL TIME DETAILS
12026-04-25T01:17:46.918Zjob dependencies complete; ready to run (waiting for 0 s)
22026-04-25T01:20:58.219Zjob assigned to worker 01KQ13DNKWTK5JKWA58P9WH1SJ [factory edgar, gimlet/BRM42220010/844] (queued for 3 m 11 s)
32026-04-25T01:20:58.775Zdownloading input: /input/build-interop/work/testbed.tar.gz
42026-04-25T01:21:07.239Zdownloaded input: /input/build-interop/work/testbed.tar.gz
52026-04-25T01:21:07.239Zdownloading input: /input/build-interop/work/dhcp-server
62026-04-25T01:21:09.645Zdownloaded input: /input/build-interop/work/dhcp-server
72026-04-25T01:21:09.669Zdownloading input: /input/build/work/debug/ddmadm
82026-04-25T01:21:32.128Zdownloaded input: /input/build/work/debug/ddmadm
92026-04-25T01:21:32.152Zdownloading input: /input/build/work/debug/ddmd
102026-04-25T01:21:59.549Zdownloaded input: /input/build/work/debug/ddmd
112026-04-25T01:21:59.573Zdownloading input: /input/build/work/debug/mgadm
122026-04-25T01:22:25.500Zdownloaded input: /input/build/work/debug/mgadm
132026-04-25T01:22:25.500Zdownloading input: /input/build/work/debug/mgd
142026-04-25T01:22:56.239Zdownloaded input: /input/build/work/debug/mgd
152026-04-25T01:22:56.263Zdownloading input: /input/build/work/release/ddmadm
162026-04-25T01:22:58.276Zdownloaded input: /input/build/work/release/ddmadm
172026-04-25T01:22:58.300Zdownloading input: /input/build/work/release/ddmd
182026-04-25T01:23:00.608Zdownloaded input: /input/build/work/release/ddmd
192026-04-25T01:23:00.608Zdownloading input: /input/build/work/release/falcon-lab
202026-04-25T01:23:03.449Zdownloaded input: /input/build/work/release/falcon-lab
212026-04-25T01:23:03.449Zdownloading input: /input/build/work/release/mgadm
222026-04-25T01:23:05.998Zdownloaded input: /input/build/work/release/mgadm
232026-04-25T01:23:05.998Zdownloading input: /input/build/work/release/mgd
242026-04-25T01:23:09.334Zdownloaded input: /input/build/work/release/mgd
 
252026-04-25T01:23:09.334Zstarting task 0: "setup"
262026-04-25T01:23:09.359Z++ uname -s
272026-04-25T01:23:09.359Z+ kern=SunOS
282026-04-25T01:23:09.359Z+ build_user=build
292026-04-25T01:23:09.359Z+ build_uid=12345
302026-04-25T01:23:09.359Z+ work_dir=/work
312026-04-25T01:23:09.359Z+ input_dir=/input
322026-04-25T01:23:09.359Z+ [[ 0 == 12345 ]]
332026-04-25T01:23:09.359Z+ case "$kern" in
342026-04-25T01:23:09.359Z+ groupadd -g 12345 build
352026-04-25T01:23:09.383Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
362026-04-25T01:23:11.370Z+ zfs create -o mountpoint=/work rpool/work
372026-04-25T01:23:12.094Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
382026-04-25T01:23:12.118Z+ home_fs=
392026-04-25T01:23:12.118Z+ [[ '' == autofs ]]
402026-04-25T01:23:12.118Z+ mkdir -p /home/build
412026-04-25T01:23:12.119Z+ chown build:build /home/build /work
422026-04-25T01:23:13.108Z+ chmod 0700 /home/build /work
432026-04-25T01:23:13.132Zprocess exited: duration 3776 ms, exit code 0
 
442026-04-25T01:23:13.180Zstarting task 1: "authentication"
452026-04-25T01:23:13.276Zprocess exited: duration 95 ms, exit code 0
 
462026-04-25T01:23:13.324Zstarting task 2: "build"
472026-04-25T01:23:13.349Z+ set -e
482026-04-25T01:23:13.349Z+ banner zpool
492026-04-25T01:23:13.349Z
502026-04-25T01:23:13.349Z ###### ##### #### #### #
512026-04-25T01:23:13.349Z # # # # # # # #
522026-04-25T01:23:13.349Z # # # # # # # #
532026-04-25T01:23:13.349Z # ##### # # # # #
542026-04-25T01:23:13.349Z # # # # # # #
552026-04-25T01:23:13.349Z ###### # #### #### ######
562026-04-25T01:23:13.349Z
572026-04-25T01:23:13.349Z++ pfexec diskinfo -pH
582026-04-25T01:23:13.349Z++ sort -k8 -n -r
592026-04-25T01:23:13.373Z++ head -1
602026-04-25T01:23:13.373Z++ awk '{print $2}'
612026-04-25T01:23:13.397Z+ DISK=c9t0014EE81000BC3B1d0
622026-04-25T01:23:13.397Z+ export DISK
632026-04-25T01:23:13.397Z+ pfexec zpool create -o ashift=12 -f cpool c9t0014EE81000BC3B1d0
642026-04-25T01:23:13.461Z+ pfexec zfs create -o mountpoint=/ci cpool/ci
652026-04-25T01:23:13.488Z++ curl -s http://catacomb.eng.oxide.computer:12346/trim-me
662026-04-25T01:23:13.604Z+ [[ true =~ true ]]
672026-04-25T01:23:13.628Z+ pfexec zpool trim cpool
682026-04-25T01:23:13.628Z++ zpool status -t cpool
692026-04-25T01:23:13.652Z+ [[ ! pool: cpool
702026-04-25T01:23:13.652Z state: ONLINE
712026-04-25T01:23:13.652Z scan: none requested
722026-04-25T01:23:13.652Zconfig:
732026-04-25T01:23:13.652Z
742026-04-25T01:23:13.652Z NAME STATE READ WRITE CKSUM
752026-04-25T01:23:13.652Z cpool ONLINE 0 0 0
762026-04-25T01:23:13.652Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (1% trimmed, started at April 25, 2026 at 01:23:13 AM UTC)
772026-04-25T01:23:13.652Z
782026-04-25T01:23:13.652Zerrors: No known data errors =~ 100% ]]
792026-04-25T01:23:13.652Z+ sleep 10
802026-04-25T01:23:23.638Z++ zpool status -t cpool
812026-04-25T01:23:23.662Z+ [[ ! pool: cpool
822026-04-25T01:23:23.662Z state: ONLINE
832026-04-25T01:23:23.662Z scan: none requested
842026-04-25T01:23:23.662Zconfig:
852026-04-25T01:23:23.662Z
862026-04-25T01:23:23.662Z NAME STATE READ WRITE CKSUM
872026-04-25T01:23:23.662Z cpool ONLINE 0 0 0
882026-04-25T01:23:23.662Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (69% trimmed, started at April 25, 2026 at 01:23:13 AM UTC)
892026-04-25T01:23:23.662Z
902026-04-25T01:23:23.662Zerrors: No known data errors =~ 100% ]]
912026-04-25T01:23:23.662Z+ sleep 10
922026-04-25T01:23:33.652Z++ zpool status -t cpool
932026-04-25T01:23:33.676Z+ [[ ! pool: cpool
942026-04-25T01:23:33.676Z state: ONLINE
952026-04-25T01:23:33.676Z scan: none requested
962026-04-25T01:23:33.676Zconfig:
972026-04-25T01:23:33.676Z
982026-04-25T01:23:33.676Z NAME STATE READ WRITE CKSUM
992026-04-25T01:23:33.676Z cpool ONLINE 0 0 0
1002026-04-25T01:23:33.676Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (100% trimmed, completed at April 25, 2026 at 01:23:28 AM UTC)
1012026-04-25T01:23:33.676Z
1022026-04-25T01:23:33.677Zerrors: No known data errors =~ 100% ]]
1032026-04-25T01:23:33.677Z+ pfexec chown 12345 /ci
1042026-04-25T01:23:33.677Z+ cd /ci
1052026-04-25T01:23:33.677Z+ export FALCON_DATASET=cpool/falcon
1062026-04-25T01:23:33.677Z+ FALCON_DATASET=cpool/falcon
1072026-04-25T01:23:33.677Z+ banner setup
1082026-04-25T01:23:33.677Z
1092026-04-25T01:23:33.677Z #### ###### ##### # # #####
1102026-04-25T01:23:33.677Z # # # # # # #
1112026-04-25T01:23:33.677Z #### ##### # # # # #
1122026-04-25T01:23:33.677Z # # # # # #####
1132026-04-25T01:23:33.677Z # # # # # # #
1142026-04-25T01:23:33.677Z #### ###### # #### #
1152026-04-25T01:23:33.677Z
1162026-04-25T01:23:33.677Z+ cp /input/build-interop/work/dhcp-server .
1172026-04-25T01:23:34.016Z+ cp /input/build/work/release/falcon-lab .
1182026-04-25T01:23:34.074Z+ cp /input/build/work/release/mgd .
1192026-04-25T01:23:34.150Z+ cp /input/build/work/release/ddmd .
1202026-04-25T01:23:34.211Z+ chmod +x dhcp-server falcon-lab mgd ddmd
1212026-04-25T01:23:34.235Z+ mkdir -p cargo-bay
1222026-04-25T01:23:34.235Z+ mv mgd cargo-bay/
1232026-04-25T01:23:34.235Z+ mv ddmd cargo-bay/
1242026-04-25T01:23:34.235Z+ export EXT_INTERFACE=igb0
1252026-04-25T01:23:34.235Z+ EXT_INTERFACE=igb0
1262026-04-25T01:23:34.235Z++ bmat address ls -f extra -Ho first
1272026-04-25T01:23:34.259Z+ first=10.151.6.164
1282026-04-25T01:23:34.259Z++ bmat address ls -f extra -Ho last
1292026-04-25T01:23:34.283Z+ last=10.151.6.227
1302026-04-25T01:23:34.283Z++ bmat address ls -f extra -Ho gateway
1312026-04-25T01:23:34.307Z+ gw=10.151.6.1
1322026-04-25T01:23:34.307Z++ ipadm show-addr igb0/dhcp -po ADDR
1332026-04-25T01:23:34.331Z++ sed 's#/.*##g'
1342026-04-25T01:23:34.331Z+ server=10.151.6.100
1352026-04-25T01:23:34.331Z+ RUST_LOG=debug
1362026-04-25T01:23:34.331Z+ pfexec ./falcon-lab run trio-unnumbered
1372026-04-25T01:23:34.331Z+ pfexec ./dhcp-server 10.151.6.164 10.151.6.227 10.151.6.1 10.151.6.100
1382026-04-25T01:23:34.355ZApr 25 01:23:34.324 DEBG using default route interface igb0
1392026-04-25T01:23:34.355ZApr 25 01:23:34.324 DEBG using default route interface igb0
1402026-04-25T01:23:34.355ZApr 25 01:23:34.324 DEBG using default route interface igb0
1412026-04-25T01:23:34.355ZApr 25 01:23:34.324 INFO launching runner: deployment(mgtriou) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
1422026-04-25T01:23:34.355ZApr 25 01:23:34.324 INFO starting preflight for deployment mgtriou
1432026-04-25T01:23:34.355ZApr 25 01:23:34.324 INFO propolis-server binary not found
1442026-04-25T01:23:34.355ZApr 25 01:23:34.324 INFO downloading propolis server rev 36f20be9bb4c3b362029237f5feb6377c982395f, writing to .falcon/bin/propolis-server
1452026-04-25T01:23:38.228ZApr 25 01:23:38.215 INFO ovmf fd not found
1462026-04-25T01:23:38.228ZApr 25 01:23:38.215 INFO downloading ovmf
1472026-04-25T01:23:38.628ZApr 25 01:23:38.615 INFO base image for helios-2.9 does not exist, attempting to install
1482026-04-25T01:23:38.628ZApr 25 01:23:38.615 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/helios-2.9_0.raw.xz
1492026-04-25T01:24:07.423ZApr 25 01:24:07.409 INFO extracting image to /tmp/helios-2.9_0.raw
1502026-04-25T01:24:41.062ZApr 25 01:24:41.046 INFO creating zvol cpool/falcon/img/helios-2.9 of size 4508880896
1512026-04-25T01:24:41.113ZApr 25 01:24:41.098 INFO copying image data to zvol
1522026-04-25T01:24:51.437ZApr 25 01:24:51.422 INFO creating zfs snapshot cpool/falcon/img/helios-2.9@base
1532026-04-25T01:24:54.674ZApr 25 01:24:54.658 INFO base image for debian-13.2 does not exist, attempting to install
1542026-04-25T01:24:54.674ZApr 25 01:24:54.658 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz
1552026-04-25T01:25:15.234ZApr 25 01:25:15.218 INFO extracting image to /tmp/debian-13.2_0.raw
1562026-04-25T01:25:36.115ZApr 25 01:25:36.098 INFO creating zvol cpool/falcon/img/debian-13.2 of size 3221229568
1572026-04-25T01:25:36.146ZApr 25 01:25:36.130 INFO copying image data to zvol
1582026-04-25T01:25:42.163ZApr 25 01:25:42.147 INFO creating zfs snapshot cpool/falcon/img/debian-13.2@base
1592026-04-25T01:25:45.569ZApr 25 01:25:45.554 INFO base image for eos-4.35 does not exist, attempting to install
1602026-04-25T01:25:45.569ZApr 25 01:25:45.554 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz
1612026-04-25T01:26:29.508ZApr 25 01:26:29.493 INFO extracting image to /tmp/eos-4.35_0.raw
1622026-04-25T01:27:53.377ZApr 25 01:27:53.362 INFO creating zvol cpool/falcon/img/eos-4.35 of size 21474840576
1632026-04-25T01:27:53.403ZApr 25 01:27:53.389 INFO copying image data to zvol
1642026-04-25T01:28:41.476ZApr 25 01:28:41.462 INFO creating zfs snapshot cpool/falcon/img/eos-4.35@base
1652026-04-25T01:28:44.921ZApr 25 01:28:44.908 INFO creating links
1662026-04-25T01:28:44.921ZApr 25 01:28:44.908 DEBG destroying link mgtriou_ox_sn_vnic0
1672026-04-25T01:28:44.947ZApr 25 01:28:44.908 DEBG destroying link mgtriou_ox_sn_sim0
1682026-04-25T01:28:44.947ZApr 25 01:28:44.908 INFO creating simnet link 'mgtriou_ox_sn_sim0'
1692026-04-25T01:28:44.947ZApr 25 01:28:44.910 INFO creating vnic link 'mgtriou_ox_sn_vnic0'
1702026-04-25T01:28:44.947ZApr 25 01:28:44.918 DEBG link pair created
1712026-04-25T01:28:44.947ZApr 25 01:28:44.918 DEBG destroying link mgtriou_cr1_vn_vnic0
1722026-04-25T01:28:44.947ZApr 25 01:28:44.918 DEBG destroying link mgtriou_cr1_vn_sim0
1732026-04-25T01:28:44.947ZApr 25 01:28:44.918 INFO creating simnet link 'mgtriou_cr1_vn_sim0'
1742026-04-25T01:28:44.947ZApr 25 01:28:44.919 INFO creating vnic link 'mgtriou_cr1_vn_vnic0'
1752026-04-25T01:28:44.947ZApr 25 01:28:44.925 DEBG link pair created
1762026-04-25T01:28:44.947ZApr 25 01:28:44.926 DEBG destroying link mgtriou_ox_sn_vnic1
1772026-04-25T01:28:44.947ZApr 25 01:28:44.926 DEBG destroying link mgtriou_ox_sn_sim1
1782026-04-25T01:28:44.947ZApr 25 01:28:44.926 INFO creating simnet link 'mgtriou_ox_sn_sim1'
1792026-04-25T01:28:44.947ZApr 25 01:28:44.928 INFO creating vnic link 'mgtriou_ox_sn_vnic1'
1802026-04-25T01:28:44.972ZApr 25 01:28:44.935 DEBG link pair created
1812026-04-25T01:28:44.972ZApr 25 01:28:44.935 DEBG destroying link mgtriou_cr2_vn_vnic0
1822026-04-25T01:28:44.972ZApr 25 01:28:44.935 DEBG destroying link mgtriou_cr2_vn_sim0
1832026-04-25T01:28:44.972ZApr 25 01:28:44.935 INFO creating simnet link 'mgtriou_cr2_vn_sim0'
1842026-04-25T01:28:44.972ZApr 25 01:28:44.936 INFO creating vnic link 'mgtriou_cr2_vn_vnic0'
1852026-04-25T01:28:44.972ZApr 25 01:28:44.942 DEBG link pair created
1862026-04-25T01:28:44.972ZApr 25 01:28:44.942 INFO creating external links
1872026-04-25T01:28:44.972ZApr 25 01:28:44.942 DEBG destroying external link mgtriou_ox_vn_vnic2
1882026-04-25T01:28:44.972ZApr 25 01:28:44.942 INFO creating external link mgtriou_ox_vn_vnic2
1892026-04-25T01:28:44.972ZApr 25 01:28:44.944 DEBG external link mgtriou_ox_vn_vnic2@igb0 created
1902026-04-25T01:28:44.972ZApr 25 01:28:44.944 DEBG destroying external link mgtriou_cr1_vn_vnic1
1912026-04-25T01:28:44.972ZApr 25 01:28:44.944 INFO creating external link mgtriou_cr1_vn_vnic1
1922026-04-25T01:28:44.972ZApr 25 01:28:44.946 DEBG external link mgtriou_cr1_vn_vnic1@igb0 created
1932026-04-25T01:28:44.972ZApr 25 01:28:44.946 DEBG destroying external link mgtriou_cr2_vn_vnic1
1942026-04-25T01:28:44.972ZApr 25 01:28:44.946 INFO creating external link mgtriou_cr2_vn_vnic1
1952026-04-25T01:28:44.972ZApr 25 01:28:44.947 DEBG external link mgtriou_cr2_vn_vnic1@igb0 created
1962026-04-25T01:28:44.972ZApr 25 01:28:44.947 INFO creating nodes
1972026-04-25T01:28:44.972ZApr 25 01:28:44.947 INFO ox: launching node
1982026-04-25T01:28:44.972ZApr 25 01:28:44.949 INFO cr1: launching node
1992026-04-25T01:28:44.972ZApr 25 01:28:44.952 INFO cr2: launching node
2002026-04-25T01:28:44.996ZApr 25 01:28:44.965 INFO launched instance ox with pid 856 on port 40432
2012026-04-25T01:28:44.996ZApr 25 01:28:44.966 INFO ox: instance ensure
2022026-04-25T01:28:44.996ZApr 25 01:28:44.966 INFO launched instance cr1 with pid 857 on port 60987
2032026-04-25T01:28:44.996ZApr 25 01:28:44.966 INFO cr1: instance ensure
2042026-04-25T01:28:44.996ZApr 25 01:28:44.967 INFO launched instance cr2 with pid 858 on port 48169
2052026-04-25T01:28:44.997ZApr 25 01:28:44.967 INFO cr2: instance ensure
2062026-04-25T01:28:47.351ZApr 25 01:28:47.338 INFO ox: instance run
2072026-04-25T01:28:47.375ZApr 25 01:28:47.338 DEBG [sc] ox: starting
2082026-04-25T01:28:47.375ZApr 25 01:28:47.338 DEBG [sc] ox: connecting to [::1]:40432
2092026-04-25T01:28:47.375ZApr 25 01:28:47.339 DEBG [sc] ox waiting for prompt
2102026-04-25T01:28:47.376ZApr 25 01:28:47.343 INFO cr1: instance run
2112026-04-25T01:28:47.376ZApr 25 01:28:47.344 DEBG [sc] cr1: starting
2122026-04-25T01:28:47.376ZApr 25 01:28:47.344 DEBG [sc] cr1: connecting to [::1]:60987
2132026-04-25T01:28:47.376ZApr 25 01:28:47.344 DEBG [sc] cr1 waiting for prompt
2142026-04-25T01:28:47.400ZApr 25 01:28:47.368 INFO cr2: instance run
2152026-04-25T01:28:47.400ZApr 25 01:28:47.369 DEBG [sc] cr2: starting
2162026-04-25T01:28:47.400ZApr 25 01:28:47.369 DEBG [sc] cr2: connecting to [::1]:48169
2172026-04-25T01:28:47.400ZApr 25 01:28:47.369 DEBG [sc] cr2 waiting for prompt
2182026-04-25T01:29:04.495ZApr 25 01:29:04.482 DEBG [sc] cr1: logging in
2192026-04-25T01:29:04.893ZApr 25 01:29:04.878 INFO cr1: mounting /opt/cargo-bay
2202026-04-25T01:29:04.893ZApr 25 01:29:04.878 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2212026-04-25T01:29:04.918ZApr 25 01:29:04.889 DEBG [sc] cr1: executing command `cd`
2222026-04-25T01:29:04.918ZApr 25 01:29:04.900 INFO cr1: finished mounting /opt/cargo-bay
2232026-04-25T01:29:04.918ZApr 25 01:29:04.900 DEBG [sc] cr1: executing command `hostname cr1`
2242026-04-25T01:29:04.942ZApr 25 01:29:04.911 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
2252026-04-25T01:29:04.942ZApr 25 01:29:04.922 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
2262026-04-25T01:29:04.966ZApr 25 01:29:04.932 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
2272026-04-25T01:29:04.966ZApr 25 01:29:04.944 INFO cr1: logging out
2282026-04-25T01:29:07.021ZApr 25 01:29:07.008 INFO cr1: logged out
2292026-04-25T01:29:07.950ZApr 25 01:29:07.937 DEBG [sc] ox: logging in
2302026-04-25T01:29:08.123ZApr 25 01:29:08.110 INFO ox: mounting /opt/cargo-bay
2312026-04-25T01:29:08.123ZApr 25 01:29:08.110 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2322026-04-25T01:29:08.990ZApr 25 01:29:08.977 DEBG [sc] cr2: logging in
2332026-04-25T01:29:09.294ZApr 25 01:29:09.281 DEBG [sc] ox: executing command `cd`
2342026-04-25T01:29:09.319ZApr 25 01:29:09.292 INFO ox: finished mounting /opt/cargo-bay
2352026-04-25T01:29:09.319ZApr 25 01:29:09.292 DEBG [sc] ox: executing command `hostname ox`
2362026-04-25T01:29:09.319ZApr 25 01:29:09.303 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
2372026-04-25T01:29:09.343ZApr 25 01:29:09.314 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
2382026-04-25T01:29:09.343ZApr 25 01:29:09.325 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
2392026-04-25T01:29:09.367ZApr 25 01:29:09.336 INFO ox: logging out
2402026-04-25T01:29:09.427ZApr 25 01:29:09.413 INFO ox: logged out
2412026-04-25T01:29:09.478ZApr 25 01:29:09.465 INFO cr2: mounting /opt/cargo-bay
2422026-04-25T01:29:09.478ZApr 25 01:29:09.465 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2432026-04-25T01:29:09.502ZApr 25 01:29:09.476 DEBG [sc] cr2: executing command `cd`
2442026-04-25T01:29:09.502ZApr 25 01:29:09.487 INFO cr2: finished mounting /opt/cargo-bay
2452026-04-25T01:29:09.502ZApr 25 01:29:09.487 DEBG [sc] cr2: executing command `hostname cr2`
2462026-04-25T01:29:09.526ZApr 25 01:29:09.498 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
2472026-04-25T01:29:09.526ZApr 25 01:29:09.508 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
2482026-04-25T01:29:09.550ZApr 25 01:29:09.520 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
2492026-04-25T01:29:09.550ZApr 25 01:29:09.531 INFO cr2: logging out
2502026-04-25T01:29:12.483ZApr 25 01:29:12.470 INFO cr2: logged out
2512026-04-25T01:29:12.507ZApr 25 01:29:12.470 DEBG [sc] ox: starting
2522026-04-25T01:29:12.507ZApr 25 01:29:12.470 DEBG [sc] ox: connecting to [::1]:40432
2532026-04-25T01:29:12.507ZApr 25 01:29:12.471 DEBG [sc] ox waiting for prompt
2542026-04-25T01:29:12.507ZApr 25 01:29:12.481 DEBG [sc] ox: logging in
2552026-04-25T01:29:12.583ZApr 25 01:29:12.570 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
2562026-04-25T01:29:18.947ZApr 25 01:29:18.934 DEBG [sc] ox: starting
2572026-04-25T01:29:18.947ZApr 25 01:29:18.934 DEBG [sc] ox: connecting to [::1]:40432
2582026-04-25T01:29:18.971ZApr 25 01:29:18.934 DEBG [sc] ox waiting for prompt
2592026-04-25T01:29:18.971ZApr 25 01:29:18.944 DEBG [sc] ox: logging in
2602026-04-25T01:29:19.046ZApr 25 01:29:19.033 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
2612026-04-25T01:29:19.134ZApr 25 01:29:19.121 DEBG [sc] ox: starting
2622026-04-25T01:29:19.134ZApr 25 01:29:19.121 DEBG [sc] ox: connecting to [::1]:40432
2632026-04-25T01:29:19.158ZApr 25 01:29:19.122 DEBG [sc] ox waiting for prompt
2642026-04-25T01:29:19.158ZApr 25 01:29:19.132 DEBG [sc] ox: logging in
2652026-04-25T01:29:19.233ZApr 25 01:29:19.220 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
2662026-04-25T01:29:19.300ZApr 25 01:29:19.287 INFO cr1: installing frr
2672026-04-25T01:29:19.300ZApr 25 01:29:19.287 INFO ox: setting up npuvm
2682026-04-25T01:29:19.300ZApr 25 01:29:19.287 INFO waiting for ceos to initialize
2692026-04-25T01:29:19.324ZApr 25 01:29:19.287 DEBG [sc] cr2: starting
2702026-04-25T01:29:19.324ZApr 25 01:29:19.287 DEBG [sc] cr2: connecting to [::1]:48169
2712026-04-25T01:29:19.324ZApr 25 01:29:19.287 DEBG [sc] cr1: starting
2722026-04-25T01:29:19.324ZApr 25 01:29:19.287 DEBG [sc] cr1: connecting to [::1]:60987
2732026-04-25T01:29:19.324ZApr 25 01:29:19.287 DEBG [sc] ox: starting
2742026-04-25T01:29:19.324ZApr 25 01:29:19.287 DEBG [sc] ox: connecting to [::1]:40432
2752026-04-25T01:29:19.324ZApr 25 01:29:19.288 DEBG [sc] ox waiting for prompt
2762026-04-25T01:29:19.324ZApr 25 01:29:19.288 DEBG [sc] cr2 waiting for prompt
2772026-04-25T01:29:19.324ZApr 25 01:29:19.288 DEBG [sc] cr1 waiting for prompt
2782026-04-25T01:29:19.324ZApr 25 01:29:19.298 DEBG [sc] ox: logging in
2792026-04-25T01:29:19.324ZApr 25 01:29:19.299 DEBG [sc] cr2: logging in
2802026-04-25T01:29:19.324ZApr 25 01:29:19.299 DEBG [sc] cr1: logging in
2812026-04-25T01:29:19.399ZApr 25 01:29:19.386 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
2822026-04-25T01:29:19.444ZApr 25 01:29:19.431 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
2832026-04-25T01:29:19.638ZApr 25 01:29:19.625 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
2842026-04-25T01:29:21.687ZApr 25 01:29:21.674 INFO cr2: executing eos script show version
2852026-04-25T01:29:21.688ZApr 25 01:29:21.674 DEBG [sc] cr2: starting
2862026-04-25T01:29:21.688ZApr 25 01:29:21.674 DEBG [sc] cr2: connecting to [::1]:48169
2872026-04-25T01:29:21.712ZApr 25 01:29:21.675 DEBG [sc] cr2 waiting for prompt
2882026-04-25T01:29:21.712ZApr 25 01:29:21.685 DEBG [sc] cr2: logging in
2892026-04-25T01:29:21.842ZApr 25 01:29:21.829 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
2902026-04-25T01:29:24.808ZApr 25 01:29:24.794 DEBG [sc] ox: starting
2912026-04-25T01:29:24.808ZApr 25 01:29:24.794 DEBG [sc] ox: connecting to [::1]:40432
2922026-04-25T01:29:24.832ZApr 25 01:29:24.795 DEBG [sc] ox waiting for prompt
2932026-04-25T01:29:24.832ZApr 25 01:29:24.805 DEBG [sc] ox: logging in
2942026-04-25T01:29:24.906ZApr 25 01:29:24.893 DEBG [sc] ox: executing command `chmod +x npuvm`
2952026-04-25T01:29:24.973ZApr 25 01:29:24.960 DEBG [sc] ox: starting
2962026-04-25T01:29:24.973ZApr 25 01:29:24.960 DEBG [sc] ox: connecting to [::1]:40432
2972026-04-25T01:29:24.997ZApr 25 01:29:24.960 DEBG [sc] ox waiting for prompt
2982026-04-25T01:29:24.997ZApr 25 01:29:24.971 DEBG [sc] ox: logging in
2992026-04-25T01:29:25.060ZApr 25 01:29:25.047 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
3002026-04-25T01:29:29.919ZApr 25 01:29:29.906 DEBG [sc] cr2: starting
3012026-04-25T01:29:29.919ZApr 25 01:29:29.906 DEBG [sc] cr2: connecting to [::1]:48169
3022026-04-25T01:29:29.943ZApr 25 01:29:29.906 DEBG [sc] cr2 waiting for prompt
3032026-04-25T01:29:29.943ZApr 25 01:29:29.917 DEBG [sc] cr2: logging in
3042026-04-25T01:29:30.064ZApr 25 01:29:30.049 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3052026-04-25T01:29:32.161ZApr 25 01:29:32.148 INFO cr2: executing eos script show version
3062026-04-25T01:29:32.161ZApr 25 01:29:32.148 DEBG [sc] cr2: starting
3072026-04-25T01:29:32.161ZApr 25 01:29:32.148 DEBG [sc] cr2: connecting to [::1]:48169
3082026-04-25T01:29:32.185ZApr 25 01:29:32.149 DEBG [sc] cr2 waiting for prompt
3092026-04-25T01:29:32.185ZApr 25 01:29:32.159 DEBG [sc] cr2: logging in
3102026-04-25T01:29:32.326ZApr 25 01:29:32.314 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3112026-04-25T01:29:34.688ZApr 25 01:29:34.676 DEBG [sc] cr2: starting
3122026-04-25T01:29:34.688ZApr 25 01:29:34.676 DEBG [sc] cr2: connecting to [::1]:48169
3132026-04-25T01:29:34.712ZApr 25 01:29:34.677 DEBG [sc] cr2 waiting for prompt
3142026-04-25T01:29:34.712ZApr 25 01:29:34.687 DEBG [sc] cr2: logging in
3152026-04-25T01:29:34.843ZApr 25 01:29:34.831 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3162026-04-25T01:29:37.034ZApr 25 01:29:37.021 INFO cr2: executing eos script show version
3172026-04-25T01:29:37.034ZApr 25 01:29:37.021 DEBG [sc] cr2: starting
3182026-04-25T01:29:37.034ZApr 25 01:29:37.021 DEBG [sc] cr2: connecting to [::1]:48169
3192026-04-25T01:29:37.059ZApr 25 01:29:37.022 DEBG [sc] cr2 waiting for prompt
3202026-04-25T01:29:37.059ZApr 25 01:29:37.032 DEBG [sc] cr2: logging in
3212026-04-25T01:29:37.176ZApr 25 01:29:37.164 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3222026-04-25T01:29:39.681ZApr 25 01:29:39.669 INFO cr2: executing eos script
3232026-04-25T01:29:39.681Z enable
3242026-04-25T01:29:39.681Z configure
3252026-04-25T01:29:39.681Z ipv6 unicast-routing
3262026-04-25T01:29:39.681Z ip routing ipv6 interfaces
3272026-04-25T01:29:39.681Z ip routing
3282026-04-25T01:29:39.681Z ip route 1.2.3.0/24 null0
3292026-04-25T01:29:39.681Z ipv6 route fd99::/64 null0
3302026-04-25T01:29:39.681Z interface et1
3312026-04-25T01:29:39.681Z no switchport
3322026-04-25T01:29:39.681Z ipv6 enable
3332026-04-25T01:29:39.681Z
3342026-04-25T01:29:39.681Z router bgp 45
3352026-04-25T01:29:39.681Z router-id 1.2.3.1
3362026-04-25T01:29:39.681Z no bgp default ipv4-unicast
3372026-04-25T01:29:39.681Z timers bgp 2 6
3382026-04-25T01:29:39.681Z neighbor ebgp peer group
3392026-04-25T01:29:39.681Z neighbor ebgp remote-as 33
3402026-04-25T01:29:39.682Z neighbor interface Et1 peer-group ebgp
3412026-04-25T01:29:39.682Z address-family ipv4
3422026-04-25T01:29:39.682Z neighbor ebgp activate
3432026-04-25T01:29:39.682Z neighbor ebgp next-hop address-family ipv6 originate
3442026-04-25T01:29:39.682Z network 1.2.3.0/24
3452026-04-25T01:29:39.682Z exit
3462026-04-25T01:29:39.682Z address-family ipv6
3472026-04-25T01:29:39.682Z neighbor ebgp activate
3482026-04-25T01:29:39.682Z neighbor ebgp next-hop address-family ipv6 originate
3492026-04-25T01:29:39.682Z network fd99::/64
3502026-04-25T01:29:39.682Z exit
3512026-04-25T01:29:39.682Z exit
3522026-04-25T01:29:39.682Z
3532026-04-25T01:29:39.682ZApr 25 01:29:39.669 DEBG [sc] cr2: starting
3542026-04-25T01:29:39.682ZApr 25 01:29:39.669 DEBG [sc] cr2: connecting to [::1]:48169
3552026-04-25T01:29:39.706ZApr 25 01:29:39.669 DEBG [sc] cr2 waiting for prompt
3562026-04-25T01:29:39.706ZApr 25 01:29:39.680 DEBG [sc] cr2: logging in
3572026-04-25T01:29:39.835ZApr 25 01:29:39.823 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
3582026-04-25T01:29:39.836Z enable
3592026-04-25T01:29:39.836Z configure
3602026-04-25T01:29:39.836Z ipv6 unicast-routing
3612026-04-25T01:29:39.836Z ip routing ipv6 interfaces
3622026-04-25T01:29:39.836Z ip routing
3632026-04-25T01:29:39.836Z ip route 1.2.3.0/24 null0
3642026-04-25T01:29:39.836Z ipv6 route fd99::/64 null0
3652026-04-25T01:29:39.836Z interface et1
3662026-04-25T01:29:39.836Z no switchport
3672026-04-25T01:29:39.836Z ipv6 enable
3682026-04-25T01:29:39.836Z
3692026-04-25T01:29:39.836Z router bgp 45
3702026-04-25T01:29:39.836Z router-id 1.2.3.1
3712026-04-25T01:29:39.836Z no bgp default ipv4-unicast
3722026-04-25T01:29:39.836Z timers bgp 2 6
3732026-04-25T01:29:39.836Z neighbor ebgp peer group
3742026-04-25T01:29:39.836Z neighbor ebgp remote-as 33
3752026-04-25T01:29:39.836Z neighbor interface Et1 peer-group ebgp
3762026-04-25T01:29:39.836Z address-family ipv4
3772026-04-25T01:29:39.836Z neighbor ebgp activate
3782026-04-25T01:29:39.836Z neighbor ebgp next-hop address-family ipv6 originate
3792026-04-25T01:29:39.836Z network 1.2.3.0/24
3802026-04-25T01:29:39.836Z exit
3812026-04-25T01:29:39.836Z address-family ipv6
3822026-04-25T01:29:39.836Z neighbor ebgp activate
3832026-04-25T01:29:39.836Z neighbor ebgp next-hop address-family ipv6 originate
3842026-04-25T01:29:39.836Z network fd99::/64
3852026-04-25T01:29:39.836Z exit
3862026-04-25T01:29:39.836Z exit
3872026-04-25T01:29:39.836Z '`
3882026-04-25T01:29:56.831ZApr 25 01:29:56.819 INFO cr1: enabling frr daemon bgpd
3892026-04-25T01:29:56.831ZApr 25 01:29:56.819 DEBG [sc] cr1: starting
3902026-04-25T01:29:56.831ZApr 25 01:29:56.819 DEBG [sc] cr1: connecting to [::1]:60987
3912026-04-25T01:29:56.855ZApr 25 01:29:56.819 DEBG [sc] cr1 waiting for prompt
3922026-04-25T01:29:56.855ZApr 25 01:29:56.830 DEBG [sc] cr1: logging in
3932026-04-25T01:29:56.973ZApr 25 01:29:56.961 DEBG [sc] cr1: executing command `sed -i 's/bgpd=no/bgpd=yes/g' /etc/frr/daemons`
3942026-04-25T01:29:59.042ZApr 25 01:29:59.029 DEBG [sc] cr1: starting
3952026-04-25T01:29:59.042ZApr 25 01:29:59.029 DEBG [sc] cr1: connecting to [::1]:60987
3962026-04-25T01:29:59.066ZApr 25 01:29:59.030 DEBG [sc] cr1 waiting for prompt
3972026-04-25T01:29:59.066ZApr 25 01:29:59.041 DEBG [sc] cr1: logging in
3982026-04-25T01:29:59.185ZApr 25 01:29:59.173 DEBG [sc] cr1: executing command `systemctl restart frr`
3992026-04-25T01:30:06.796ZApr 25 01:30:06.784 INFO cr1: executing frr script
4002026-04-25T01:30:06.797Z configure
4012026-04-25T01:30:06.797Z ip forwarding
4022026-04-25T01:30:06.797Z ipv6 forwarding
4032026-04-25T01:30:06.797Z ip route 1.2.3.0/24 null0
4042026-04-25T01:30:06.797Z ipv6 route fd99::/64 null0
4052026-04-25T01:30:06.797Z router bgp 44
4062026-04-25T01:30:06.797Z no bgp ebgp-requires-policy
4072026-04-25T01:30:06.797Z timers bgp 2 6
4082026-04-25T01:30:06.797Z neighbor enp0s8 interface remote-as external
4092026-04-25T01:30:06.797Z neighbor enp0s8 timers connect 1
4102026-04-25T01:30:06.797Z address-family ipv4 unicast
4112026-04-25T01:30:06.797Z network 1.2.3.0/24
4122026-04-25T01:30:06.797Z neighbor enp0s8 activate
4132026-04-25T01:30:06.797Z exit-address-family
4142026-04-25T01:30:06.797Z address-family ipv6 unicast
4152026-04-25T01:30:06.797Z network fd99::/64
4162026-04-25T01:30:06.797Z neighbor enp0s8 activate
4172026-04-25T01:30:06.797Z exit-address-family
4182026-04-25T01:30:06.797Z exit
4192026-04-25T01:30:06.797Z
4202026-04-25T01:30:06.797ZApr 25 01:30:06.784 DEBG [sc] cr1: starting
4212026-04-25T01:30:06.797ZApr 25 01:30:06.784 DEBG [sc] cr1: connecting to [::1]:60987
4222026-04-25T01:30:06.822ZApr 25 01:30:06.785 DEBG [sc] cr1 waiting for prompt
4232026-04-25T01:30:06.822ZApr 25 01:30:06.796 DEBG [sc] cr1: logging in
4242026-04-25T01:30:06.951ZApr 25 01:30:06.939 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 ' '`
4252026-04-25T01:31:08.778ZApr 25 01:31:08.743 DEBG [sc] ox: starting
4262026-04-25T01:31:08.778ZApr 25 01:31:08.743 DEBG [sc] ox: connecting to [::1]:40432
4272026-04-25T01:31:08.778ZApr 25 01:31:08.744 DEBG [sc] ox waiting for prompt
4282026-04-25T01:31:08.778ZApr 25 01:31:08.754 DEBG [sc] ox: logging in
4292026-04-25T01:31:08.844ZApr 25 01:31:08.831 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
4302026-04-25T01:31:09.123ZApr 25 01:31:09.111 DEBG [sc] ox: starting
4312026-04-25T01:31:09.123ZApr 25 01:31:09.111 DEBG [sc] ox: connecting to [::1]:40432
4322026-04-25T01:31:09.147ZApr 25 01:31:09.111 DEBG [sc] ox waiting for prompt
4332026-04-25T01:31:09.147ZApr 25 01:31:09.123 DEBG [sc] ox: logging in
4342026-04-25T01:31:09.223ZApr 25 01:31:09.211 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4352026-04-25T01:31:10.247ZApr 25 01:31:10.234 DEBG [sc] ox: starting
4362026-04-25T01:31:10.247ZApr 25 01:31:10.234 DEBG [sc] ox: connecting to [::1]:40432
4372026-04-25T01:31:10.271ZApr 25 01:31:10.235 DEBG [sc] ox waiting for prompt
4382026-04-25T01:31:10.271ZApr 25 01:31:10.235 DEBG [sc] ox: logging in
4392026-04-25T01:31:10.325ZApr 25 01:31:10.313 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4402026-04-25T01:31:10.392ZApr 25 01:31:10.380 DEBG [sc] ox: starting
4412026-04-25T01:31:10.392ZApr 25 01:31:10.380 DEBG [sc] ox: connecting to [::1]:40432
4422026-04-25T01:31:10.416ZApr 25 01:31:10.380 DEBG [sc] ox waiting for prompt
4432026-04-25T01:31:10.416ZApr 25 01:31:10.391 DEBG [sc] ox: logging in
4442026-04-25T01:31:10.494ZApr 25 01:31:10.482 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
4452026-04-25T01:31:10.560ZApr 25 01:31:10.548 DEBG [sc] ox: starting
4462026-04-25T01:31:10.560ZApr 25 01:31:10.548 DEBG [sc] ox: connecting to [::1]:40432
4472026-04-25T01:31:10.585ZApr 25 01:31:10.549 DEBG [sc] ox waiting for prompt
4482026-04-25T01:31:10.585ZApr 25 01:31:10.559 DEBG [sc] ox: logging in
4492026-04-25T01:31:10.649ZApr 25 01:31:10.636 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
4502026-04-25T01:31:10.715ZApr 25 01:31:10.702 DEBG [sc] ox: starting
4512026-04-25T01:31:10.715ZApr 25 01:31:10.702 DEBG [sc] ox: connecting to [::1]:40432
4522026-04-25T01:31:10.738ZApr 25 01:31:10.703 DEBG [sc] ox waiting for prompt
4532026-04-25T01:31:10.739ZApr 25 01:31:10.714 DEBG [sc] ox: logging in
4542026-04-25T01:31:10.802ZApr 25 01:31:10.790 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
4552026-04-25T01:31:10.858ZApr 25 01:31:10.846 DEBG [sc] ox: starting
4562026-04-25T01:31:10.858ZApr 25 01:31:10.846 DEBG [sc] ox: connecting to [::1]:40432
4572026-04-25T01:31:10.882ZApr 25 01:31:10.847 DEBG [sc] ox waiting for prompt
4582026-04-25T01:31:10.883ZApr 25 01:31:10.857 DEBG [sc] ox: logging in
4592026-04-25T01:31:10.947ZApr 25 01:31:10.935 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
4602026-04-25T01:31:11.002ZApr 25 01:31:10.990 DEBG [sc] ox: starting
4612026-04-25T01:31:11.002ZApr 25 01:31:10.990 DEBG [sc] ox: connecting to [::1]:40432
4622026-04-25T01:31:11.026ZApr 25 01:31:10.991 DEBG [sc] ox waiting for prompt
4632026-04-25T01:31:11.026ZApr 25 01:31:11.000 DEBG [sc] ox: logging in
4642026-04-25T01:31:11.090ZApr 25 01:31:11.077 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
4652026-04-25T01:31:11.145ZApr 25 01:31:11.132 DEBG [sc] ox: starting
4662026-04-25T01:31:11.145ZApr 25 01:31:11.132 DEBG [sc] ox: connecting to [::1]:40432
4672026-04-25T01:31:11.169ZApr 25 01:31:11.133 DEBG [sc] ox waiting for prompt
4682026-04-25T01:31:11.169ZApr 25 01:31:11.144 DEBG [sc] ox: logging in
4692026-04-25T01:31:11.233ZApr 25 01:31:11.221 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
4702026-04-25T01:31:11.288ZApr 25 01:31:11.276 DEBG [sc] ox: starting
4712026-04-25T01:31:11.289ZApr 25 01:31:11.276 DEBG [sc] ox: connecting to [::1]:40432
4722026-04-25T01:31:11.313ZApr 25 01:31:11.277 DEBG [sc] ox waiting for prompt
4732026-04-25T01:31:11.313ZApr 25 01:31:11.287 DEBG [sc] ox: logging in
4742026-04-25T01:31:11.377ZApr 25 01:31:11.365 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
4752026-04-25T01:31:11.448ZApr 25 01:31:11.436 INFO adding BGP router to mgd
4762026-04-25T01:31:14.591ZApr 25 01:31:14.579 INFO cr1: executing frr script show ip bgp json
4772026-04-25T01:31:14.591ZApr 25 01:31:14.579 DEBG [sc] cr1: starting
4782026-04-25T01:31:14.591ZApr 25 01:31:14.579 DEBG [sc] cr1: connecting to [::1]:60987
4792026-04-25T01:31:14.616ZApr 25 01:31:14.580 DEBG [sc] cr1 waiting for prompt
4802026-04-25T01:31:14.616ZApr 25 01:31:14.590 DEBG [sc] cr1: logging in
4812026-04-25T01:31:14.932ZApr 25 01:31:14.920 DEBG [sc] cr1: executing command `vtysh -c 'show ip bgp json'`
4822026-04-25T01:31:17.078ZApr 25 01:31:17.065 INFO cr1: executing frr script show bgp json
4832026-04-25T01:31:17.078ZApr 25 01:31:17.065 DEBG [sc] cr1: starting
4842026-04-25T01:31:17.078ZApr 25 01:31:17.065 DEBG [sc] cr1: connecting to [::1]:60987
4852026-04-25T01:31:17.102ZApr 25 01:31:17.066 DEBG [sc] cr1 waiting for prompt
4862026-04-25T01:31:17.102ZApr 25 01:31:17.076 DEBG [sc] cr1: logging in
4872026-04-25T01:31:17.210ZApr 25 01:31:17.198 DEBG [sc] cr1: executing command `vtysh -c 'show bgp json'`
4882026-04-25T01:31:19.346ZApr 25 01:31:19.333 INFO cr2: executing eos script show ip bgp | json
4892026-04-25T01:31:19.346ZApr 25 01:31:19.333 DEBG [sc] cr2: starting
4902026-04-25T01:31:19.346ZApr 25 01:31:19.333 DEBG [sc] cr2: connecting to [::1]:48169
4912026-04-25T01:31:19.370ZApr 25 01:31:19.334 DEBG [sc] cr2 waiting for prompt
4922026-04-25T01:31:19.370ZApr 25 01:31:19.345 DEBG [sc] cr2: logging in
4932026-04-25T01:31:19.689ZApr 25 01:31:19.677 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ip bgp | json'`
4942026-04-25T01:31:22.063ZApr 25 01:31:22.051 INFO cr2: executing eos script show ipv6 bgp | json
4952026-04-25T01:31:22.063ZApr 25 01:31:22.051 DEBG [sc] cr2: starting
4962026-04-25T01:31:22.063ZApr 25 01:31:22.051 DEBG [sc] cr2: connecting to [::1]:48169
4972026-04-25T01:31:22.088ZApr 25 01:31:22.052 DEBG [sc] cr2 waiting for prompt
4982026-04-25T01:31:22.088ZApr 25 01:31:22.061 DEBG [sc] cr2: logging in
4992026-04-25T01:31:22.209ZApr 25 01:31:22.195 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ipv6 bgp | json'`
5002026-04-25T01:31:24.599ZApr 25 01:31:24.587 INFO trio bgp unnumbered test passed 🎉
5012026-04-25T01:31:24.599ZApr 25 01:31:24.587 INFO destroying runner for deployment mgtriou
5022026-04-25T01:31:24.599ZApr 25 01:31:24.587 INFO destroying deployment mgtriou
5032026-04-25T01:31:24.599ZApr 25 01:31:24.587 INFO destroying nodes
5042026-04-25T01:31:24.696ZApr 25 01:31:24.684 INFO destroying links
5052026-04-25T01:31:24.697ZApr 25 01:31:24.684 INFO destroying link mgtriou_ox_sn_vnic0
5062026-04-25T01:31:24.721ZApr 25 01:31:24.687 INFO destroying link mgtriou_ox_sn_sim0
5072026-04-25T01:31:24.721ZApr 25 01:31:24.688 INFO destroying link mgtriou_cr1_vn_vnic0
5082026-04-25T01:31:25.704ZApr 25 01:31:25.691 INFO destroying link mgtriou_cr1_vn_sim0
5092026-04-25T01:31:25.728ZApr 25 01:31:25.692 INFO destroying link mgtriou_ox_sn_vnic1
5102026-04-25T01:31:25.728ZApr 25 01:31:25.694 INFO destroying link mgtriou_ox_sn_sim1
5112026-04-25T01:31:25.728ZApr 25 01:31:25.695 INFO destroying link mgtriou_cr2_vn_vnic0
5122026-04-25T01:31:25.728ZApr 25 01:31:25.696 INFO destroying link mgtriou_cr2_vn_sim0
5132026-04-25T01:31:25.728ZApr 25 01:31:25.698 INFO destroying external links
5142026-04-25T01:31:25.728ZApr 25 01:31:25.698 INFO destroying external link mgtriou_ox_vn_vnic2
5152026-04-25T01:31:25.728ZApr 25 01:31:25.699 INFO destroying external link mgtriou_cr1_vn_vnic1
5162026-04-25T01:31:25.728ZApr 25 01:31:25.700 INFO destroying external link mgtriou_cr2_vn_vnic1
5172026-04-25T01:31:25.728ZApr 25 01:31:25.702 INFO destroying images
5182026-04-25T01:31:26.180ZApr 25 01:31:26.168 INFO destroying workspace at .falcon
5192026-04-25T01:31:26.204Z+ RUST_LOG=debug
5202026-04-25T01:31:26.204Z+ pfexec ./falcon-lab run trio-bfd-static-routing
5212026-04-25T01:31:26.228ZApr 25 01:31:26.207 DEBG using default route interface igb0
5222026-04-25T01:31:26.228ZApr 25 01:31:26.208 DEBG using default route interface igb0
5232026-04-25T01:31:26.228ZApr 25 01:31:26.208 DEBG using default route interface igb0
5242026-04-25T01:31:26.228ZApr 25 01:31:26.208 INFO launching runner: deployment(mgtriobfd) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
5252026-04-25T01:31:26.228ZApr 25 01:31:26.208 INFO starting preflight for deployment mgtriobfd
5262026-04-25T01:31:26.938ZApr 25 01:31:26.925 INFO creating links
5272026-04-25T01:31:26.938ZApr 25 01:31:26.925 DEBG destroying link mgtriobfd_ox_sn_vnic0
5282026-04-25T01:31:26.938ZApr 25 01:31:26.925 DEBG destroying link mgtriobfd_ox_sn_sim0
5292026-04-25T01:31:26.938ZApr 25 01:31:26.926 INFO creating simnet link 'mgtriobfd_ox_sn_sim0'
5302026-04-25T01:31:26.962ZApr 25 01:31:26.928 INFO creating vnic link 'mgtriobfd_ox_sn_vnic0'
5312026-04-25T01:31:26.962ZApr 25 01:31:26.935 DEBG link pair created
5322026-04-25T01:31:26.962ZApr 25 01:31:26.935 DEBG destroying link mgtriobfd_cr1_vn_vnic0
5332026-04-25T01:31:26.962ZApr 25 01:31:26.935 DEBG destroying link mgtriobfd_cr1_vn_sim0
5342026-04-25T01:31:26.962ZApr 25 01:31:26.935 INFO creating simnet link 'mgtriobfd_cr1_vn_sim0'
5352026-04-25T01:31:26.962ZApr 25 01:31:26.936 INFO creating vnic link 'mgtriobfd_cr1_vn_vnic0'
5362026-04-25T01:31:26.962ZApr 25 01:31:26.943 DEBG link pair created
5372026-04-25T01:31:26.962ZApr 25 01:31:26.943 DEBG destroying link mgtriobfd_ox_sn_vnic1
5382026-04-25T01:31:26.962ZApr 25 01:31:26.943 DEBG destroying link mgtriobfd_ox_sn_sim1
5392026-04-25T01:31:26.963ZApr 25 01:31:26.943 INFO creating simnet link 'mgtriobfd_ox_sn_sim1'
5402026-04-25T01:31:26.963ZApr 25 01:31:26.944 INFO creating vnic link 'mgtriobfd_ox_sn_vnic1'
5412026-04-25T01:31:26.963ZApr 25 01:31:26.950 DEBG link pair created
5422026-04-25T01:31:26.963ZApr 25 01:31:26.950 DEBG destroying link mgtriobfd_cr2_vn_vnic0
5432026-04-25T01:31:26.963ZApr 25 01:31:26.950 DEBG destroying link mgtriobfd_cr2_vn_sim0
5442026-04-25T01:31:26.963ZApr 25 01:31:26.950 INFO creating simnet link 'mgtriobfd_cr2_vn_sim0'
5452026-04-25T01:31:26.987ZApr 25 01:31:26.951 INFO creating vnic link 'mgtriobfd_cr2_vn_vnic0'
5462026-04-25T01:31:26.987ZApr 25 01:31:26.958 DEBG link pair created
5472026-04-25T01:31:26.987ZApr 25 01:31:26.958 INFO creating external links
5482026-04-25T01:31:26.987ZApr 25 01:31:26.958 DEBG destroying external link mgtriobfd_ox_vn_vnic2
5492026-04-25T01:31:26.987ZApr 25 01:31:26.958 INFO creating external link mgtriobfd_ox_vn_vnic2
5502026-04-25T01:31:26.987ZApr 25 01:31:26.960 DEBG external link mgtriobfd_ox_vn_vnic2@igb0 created
5512026-04-25T01:31:26.987ZApr 25 01:31:26.960 DEBG destroying external link mgtriobfd_cr1_vn_vnic1
5522026-04-25T01:31:26.987ZApr 25 01:31:26.960 INFO creating external link mgtriobfd_cr1_vn_vnic1
5532026-04-25T01:31:26.987ZApr 25 01:31:26.961 DEBG external link mgtriobfd_cr1_vn_vnic1@igb0 created
5542026-04-25T01:31:26.987ZApr 25 01:31:26.961 DEBG destroying external link mgtriobfd_cr2_vn_vnic1
5552026-04-25T01:31:26.987ZApr 25 01:31:26.961 INFO creating external link mgtriobfd_cr2_vn_vnic1
5562026-04-25T01:31:26.987ZApr 25 01:31:26.963 DEBG external link mgtriobfd_cr2_vn_vnic1@igb0 created
5572026-04-25T01:31:26.987ZApr 25 01:31:26.963 INFO creating nodes
5582026-04-25T01:31:26.987ZApr 25 01:31:26.963 INFO ox: launching node
5592026-04-25T01:31:26.987ZApr 25 01:31:26.965 INFO cr1: launching node
5602026-04-25T01:31:26.987ZApr 25 01:31:26.967 INFO cr2: launching node
5612026-04-25T01:31:27.011ZApr 25 01:31:26.981 INFO launched instance cr1 with pid 896 on port 64232
5622026-04-25T01:31:27.011ZApr 25 01:31:26.981 INFO cr1: instance ensure
5632026-04-25T01:31:27.011ZApr 25 01:31:26.981 INFO launched instance cr2 with pid 897 on port 45464
5642026-04-25T01:31:27.011ZApr 25 01:31:26.981 INFO cr2: instance ensure
5652026-04-25T01:31:27.011ZApr 25 01:31:26.982 INFO launched instance ox with pid 895 on port 45992
5662026-04-25T01:31:27.011ZApr 25 01:31:26.982 INFO ox: instance ensure
5672026-04-25T01:31:29.162ZApr 25 01:31:29.150 INFO cr2: instance run
5682026-04-25T01:31:29.186ZApr 25 01:31:29.150 DEBG [sc] cr2: starting
5692026-04-25T01:31:29.186ZApr 25 01:31:29.150 DEBG [sc] cr2: connecting to [::1]:45464
5702026-04-25T01:31:29.186ZApr 25 01:31:29.151 DEBG [sc] cr2 waiting for prompt
5712026-04-25T01:31:29.211ZApr 25 01:31:29.199 INFO ox: instance run
5722026-04-25T01:31:29.236ZApr 25 01:31:29.200 DEBG [sc] ox: starting
5732026-04-25T01:31:29.236ZApr 25 01:31:29.200 DEBG [sc] ox: connecting to [::1]:45992
5742026-04-25T01:31:29.236ZApr 25 01:31:29.201 DEBG [sc] ox waiting for prompt
5752026-04-25T01:31:29.260ZApr 25 01:31:29.233 INFO cr1: instance run
5762026-04-25T01:31:29.260ZApr 25 01:31:29.233 DEBG [sc] cr1: starting
5772026-04-25T01:31:29.260ZApr 25 01:31:29.233 DEBG [sc] cr1: connecting to [::1]:64232
5782026-04-25T01:31:29.260ZApr 25 01:31:29.234 DEBG [sc] cr1 waiting for prompt
5792026-04-25T01:31:46.484ZApr 25 01:31:46.471 DEBG [sc] cr1: logging in
5802026-04-25T01:31:46.857ZApr 25 01:31:46.845 INFO cr1: mounting /opt/cargo-bay
5812026-04-25T01:31:46.857ZApr 25 01:31:46.845 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5822026-04-25T01:31:46.882ZApr 25 01:31:46.856 DEBG [sc] cr1: executing command `cd`
5832026-04-25T01:31:46.882ZApr 25 01:31:46.868 INFO cr1: finished mounting /opt/cargo-bay
5842026-04-25T01:31:46.882ZApr 25 01:31:46.868 DEBG [sc] cr1: executing command `hostname cr1`
5852026-04-25T01:31:46.906ZApr 25 01:31:46.878 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
5862026-04-25T01:31:46.906ZApr 25 01:31:46.889 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
5872026-04-25T01:31:46.930ZApr 25 01:31:46.901 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
5882026-04-25T01:31:46.930ZApr 25 01:31:46.912 INFO cr1: logging out
5892026-04-25T01:31:48.992ZApr 25 01:31:48.980 INFO cr1: logged out
5902026-04-25T01:31:49.890ZApr 25 01:31:49.878 DEBG [sc] ox: logging in
5912026-04-25T01:31:50.088ZApr 25 01:31:50.076 INFO ox: mounting /opt/cargo-bay
5922026-04-25T01:31:50.088ZApr 25 01:31:50.076 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5932026-04-25T01:31:50.824ZApr 25 01:31:50.812 DEBG [sc] cr2: logging in
5942026-04-25T01:31:51.317ZApr 25 01:31:51.305 INFO cr2: mounting /opt/cargo-bay
5952026-04-25T01:31:51.317ZApr 25 01:31:51.305 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5962026-04-25T01:31:51.342ZApr 25 01:31:51.326 DEBG [sc] cr2: executing command `cd`
5972026-04-25T01:31:51.366ZApr 25 01:31:51.337 INFO cr2: finished mounting /opt/cargo-bay
5982026-04-25T01:31:51.366ZApr 25 01:31:51.337 DEBG [sc] cr2: executing command `hostname cr2`
5992026-04-25T01:31:51.366ZApr 25 01:31:51.348 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
6002026-04-25T01:31:51.390ZApr 25 01:31:51.360 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
6012026-04-25T01:31:51.390ZApr 25 01:31:51.371 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
6022026-04-25T01:31:51.414ZApr 25 01:31:51.382 INFO cr2: logging out
6032026-04-25T01:31:51.414ZApr 25 01:31:51.386 DEBG [sc] ox: executing command `cd`
6042026-04-25T01:31:51.414ZApr 25 01:31:51.397 INFO ox: finished mounting /opt/cargo-bay
6052026-04-25T01:31:51.414ZApr 25 01:31:51.397 DEBG [sc] ox: executing command `hostname ox`
6062026-04-25T01:31:51.438ZApr 25 01:31:51.409 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
6072026-04-25T01:31:51.438ZApr 25 01:31:51.420 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
6082026-04-25T01:31:51.461ZApr 25 01:31:51.431 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
6092026-04-25T01:31:51.461ZApr 25 01:31:51.441 INFO ox: logging out
6102026-04-25T01:31:51.520ZApr 25 01:31:51.508 INFO ox: logged out
6112026-04-25T01:31:54.288ZApr 25 01:31:54.276 INFO cr2: logged out
6122026-04-25T01:31:54.312ZApr 25 01:31:54.276 DEBG [sc] ox: starting
6132026-04-25T01:31:54.312ZApr 25 01:31:54.276 DEBG [sc] ox: connecting to [::1]:45992
6142026-04-25T01:31:54.312ZApr 25 01:31:54.277 DEBG [sc] ox waiting for prompt
6152026-04-25T01:31:54.312ZApr 25 01:31:54.288 DEBG [sc] ox: logging in
6162026-04-25T01:31:54.388ZApr 25 01:31:54.376 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
6172026-04-25T01:32:00.300ZApr 25 01:32:00.288 DEBG [sc] ox: starting
6182026-04-25T01:32:00.301ZApr 25 01:32:00.288 DEBG [sc] ox: connecting to [::1]:45992
6192026-04-25T01:32:00.325ZApr 25 01:32:00.289 DEBG [sc] ox waiting for prompt
6202026-04-25T01:32:00.325ZApr 25 01:32:00.299 DEBG [sc] ox: logging in
6212026-04-25T01:32:00.388ZApr 25 01:32:00.376 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
6222026-04-25T01:32:00.465ZApr 25 01:32:00.453 DEBG [sc] ox: starting
6232026-04-25T01:32:00.465ZApr 25 01:32:00.453 DEBG [sc] ox: connecting to [::1]:45992
6242026-04-25T01:32:00.489ZApr 25 01:32:00.454 DEBG [sc] ox waiting for prompt
6252026-04-25T01:32:00.489ZApr 25 01:32:00.464 DEBG [sc] ox: logging in
6262026-04-25T01:32:00.565ZApr 25 01:32:00.553 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
6272026-04-25T01:32:00.631ZApr 25 01:32:00.619 INFO cr1: installing frr
6282026-04-25T01:32:00.631ZApr 25 01:32:00.619 INFO waiting for ceos to initialize
6292026-04-25T01:32:00.655ZApr 25 01:32:00.619 INFO ox: setting up npuvm
6302026-04-25T01:32:00.655ZApr 25 01:32:00.619 DEBG [sc] cr2: starting
6312026-04-25T01:32:00.655ZApr 25 01:32:00.619 DEBG [sc] cr2: connecting to [::1]:45464
6322026-04-25T01:32:00.655ZApr 25 01:32:00.619 DEBG [sc] cr1: starting
6332026-04-25T01:32:00.655ZApr 25 01:32:00.619 DEBG [sc] cr1: connecting to [::1]:64232
6342026-04-25T01:32:00.655ZApr 25 01:32:00.619 DEBG [sc] ox: starting
6352026-04-25T01:32:00.655ZApr 25 01:32:00.619 DEBG [sc] ox: connecting to [::1]:45992
6362026-04-25T01:32:00.655ZApr 25 01:32:00.619 DEBG [sc] cr2 waiting for prompt
6372026-04-25T01:32:00.655ZApr 25 01:32:00.620 DEBG [sc] cr1 waiting for prompt
6382026-04-25T01:32:00.655ZApr 25 01:32:00.620 DEBG [sc] ox waiting for prompt
6392026-04-25T01:32:00.655ZApr 25 01:32:00.630 DEBG [sc] ox: logging in
6402026-04-25T01:32:00.655ZApr 25 01:32:00.631 DEBG [sc] cr2: logging in
6412026-04-25T01:32:00.655ZApr 25 01:32:00.631 DEBG [sc] cr1: logging in
6422026-04-25T01:32:00.719ZApr 25 01:32:00.707 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
6432026-04-25T01:32:00.786ZApr 25 01:32:00.775 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6442026-04-25T01:32:01.008ZApr 25 01:32:00.996 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
6452026-04-25T01:32:03.054ZApr 25 01:32:03.041 INFO cr2: executing eos script show version
6462026-04-25T01:32:03.054ZApr 25 01:32:03.041 DEBG [sc] cr2: starting
6472026-04-25T01:32:03.054ZApr 25 01:32:03.041 DEBG [sc] cr2: connecting to [::1]:45464
6482026-04-25T01:32:03.078ZApr 25 01:32:03.042 DEBG [sc] cr2 waiting for prompt
6492026-04-25T01:32:03.078ZApr 25 01:32:03.052 DEBG [sc] cr2: logging in
6502026-04-25T01:32:03.198ZApr 25 01:32:03.185 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6512026-04-25T01:32:07.130ZApr 25 01:32:07.118 DEBG [sc] ox: starting
6522026-04-25T01:32:07.130ZApr 25 01:32:07.118 DEBG [sc] ox: connecting to [::1]:45992
6532026-04-25T01:32:07.154ZApr 25 01:32:07.118 DEBG [sc] ox waiting for prompt
6542026-04-25T01:32:07.154ZApr 25 01:32:07.128 DEBG [sc] ox: logging in
6552026-04-25T01:32:07.218ZApr 25 01:32:07.206 DEBG [sc] ox: executing command `chmod +x npuvm`
6562026-04-25T01:32:07.285ZApr 25 01:32:07.272 DEBG [sc] ox: starting
6572026-04-25T01:32:07.285ZApr 25 01:32:07.272 DEBG [sc] ox: connecting to [::1]:45992
6582026-04-25T01:32:07.309ZApr 25 01:32:07.273 DEBG [sc] ox waiting for prompt
6592026-04-25T01:32:07.309ZApr 25 01:32:07.283 DEBG [sc] ox: logging in
6602026-04-25T01:32:07.372ZApr 25 01:32:07.360 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
6612026-04-25T01:32:11.847ZApr 25 01:32:11.835 DEBG [sc] cr2: starting
6622026-04-25T01:32:11.847ZApr 25 01:32:11.835 DEBG [sc] cr2: connecting to [::1]:45464
6632026-04-25T01:32:11.871ZApr 25 01:32:11.835 DEBG [sc] cr2 waiting for prompt
6642026-04-25T01:32:11.871ZApr 25 01:32:11.845 DEBG [sc] cr2: logging in
6652026-04-25T01:32:11.990ZApr 25 01:32:11.977 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6662026-04-25T01:32:14.108ZApr 25 01:32:14.096 INFO cr2: executing eos script show version
6672026-04-25T01:32:14.108ZApr 25 01:32:14.096 DEBG [sc] cr2: starting
6682026-04-25T01:32:14.108ZApr 25 01:32:14.096 DEBG [sc] cr2: connecting to [::1]:45464
6692026-04-25T01:32:14.132ZApr 25 01:32:14.096 DEBG [sc] cr2 waiting for prompt
6702026-04-25T01:32:14.132ZApr 25 01:32:14.106 DEBG [sc] cr2: logging in
6712026-04-25T01:32:14.272ZApr 25 01:32:14.260 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6722026-04-25T01:32:16.638ZApr 25 01:32:16.626 DEBG [sc] cr2: starting
6732026-04-25T01:32:16.638ZApr 25 01:32:16.626 DEBG [sc] cr2: connecting to [::1]:45464
6742026-04-25T01:32:16.663ZApr 25 01:32:16.626 DEBG [sc] cr2 waiting for prompt
6752026-04-25T01:32:16.663ZApr 25 01:32:16.637 DEBG [sc] cr2: logging in
6762026-04-25T01:32:16.825ZApr 25 01:32:16.813 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6772026-04-25T01:32:18.958ZApr 25 01:32:18.945 INFO cr2: executing eos script show version
6782026-04-25T01:32:18.958ZApr 25 01:32:18.946 DEBG [sc] cr2: starting
6792026-04-25T01:32:18.958ZApr 25 01:32:18.946 DEBG [sc] cr2: connecting to [::1]:45464
6802026-04-25T01:32:18.982ZApr 25 01:32:18.946 DEBG [sc] cr2 waiting for prompt
6812026-04-25T01:32:18.983ZApr 25 01:32:18.957 DEBG [sc] cr2: logging in
6822026-04-25T01:32:19.124ZApr 25 01:32:19.112 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6832026-04-25T01:32:21.560ZApr 25 01:32:21.547 DEBG [sc] cr2: starting
6842026-04-25T01:32:21.560ZApr 25 01:32:21.547 DEBG [sc] cr2: connecting to [::1]:45464
6852026-04-25T01:32:21.584ZApr 25 01:32:21.548 DEBG [sc] cr2 waiting for prompt
6862026-04-25T01:32:21.584ZApr 25 01:32:21.558 DEBG [sc] cr2: logging in
6872026-04-25T01:32:21.703ZApr 25 01:32:21.691 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6882026-04-25T01:32:23.828ZApr 25 01:32:23.815 INFO cr2: executing eos script show version
6892026-04-25T01:32:23.828ZApr 25 01:32:23.815 DEBG [sc] cr2: starting
6902026-04-25T01:32:23.828ZApr 25 01:32:23.815 DEBG [sc] cr2: connecting to [::1]:45464
6912026-04-25T01:32:23.852ZApr 25 01:32:23.816 DEBG [sc] cr2 waiting for prompt
6922026-04-25T01:32:23.852ZApr 25 01:32:23.826 DEBG [sc] cr2: logging in
6932026-04-25T01:32:23.972ZApr 25 01:32:23.960 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6942026-04-25T01:32:26.287ZApr 25 01:32:26.274 INFO cr2: executing eos script
6952026-04-25T01:32:26.287Z enable
6962026-04-25T01:32:26.287Z configure
6972026-04-25T01:32:26.287Z ip routing
6982026-04-25T01:32:26.287Z ipv6 unicast-routing
6992026-04-25T01:32:26.287Z interface Ethernet1
7002026-04-25T01:32:26.287Z no switchport
7012026-04-25T01:32:26.287Z ip address 10.0.1.2/24
7022026-04-25T01:32:26.287Z ipv6 enable
7032026-04-25T01:32:26.287Z ipv6 address fd00:2::2/64
7042026-04-25T01:32:26.287Z bfd interval 300 min-rx 300 multiplier 3
7052026-04-25T01:32:26.287Z exit
7062026-04-25T01:32:26.287Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7072026-04-25T01:32:26.287Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7082026-04-25T01:32:26.287Z exit
7092026-04-25T01:32:26.287Z
7102026-04-25T01:32:26.287ZApr 25 01:32:26.274 DEBG [sc] cr2: starting
7112026-04-25T01:32:26.287ZApr 25 01:32:26.274 DEBG [sc] cr2: connecting to [::1]:45464
7122026-04-25T01:32:26.311ZApr 25 01:32:26.275 DEBG [sc] cr2 waiting for prompt
7132026-04-25T01:32:26.311ZApr 25 01:32:26.285 DEBG [sc] cr2: logging in
7142026-04-25T01:32:26.451ZApr 25 01:32:26.439 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
7152026-04-25T01:32:26.451Z enable
7162026-04-25T01:32:26.451Z configure
7172026-04-25T01:32:26.451Z ip routing
7182026-04-25T01:32:26.451Z ipv6 unicast-routing
7192026-04-25T01:32:26.451Z interface Ethernet1
7202026-04-25T01:32:26.451Z no switchport
7212026-04-25T01:32:26.451Z ip address 10.0.1.2/24
7222026-04-25T01:32:26.451Z ipv6 enable
7232026-04-25T01:32:26.451Z ipv6 address fd00:2::2/64
7242026-04-25T01:32:26.451Z bfd interval 300 min-rx 300 multiplier 3
7252026-04-25T01:32:26.451Z exit
7262026-04-25T01:32:26.451Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7272026-04-25T01:32:26.451Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7282026-04-25T01:32:26.452Z exit
7292026-04-25T01:32:26.452Z '`
7302026-04-25T01:32:38.384ZApr 25 01:32:38.372 INFO cr1: enabling frr daemon bfdd
7312026-04-25T01:32:38.384ZApr 25 01:32:38.372 DEBG [sc] cr1: starting
7322026-04-25T01:32:38.384ZApr 25 01:32:38.372 DEBG [sc] cr1: connecting to [::1]:64232
7332026-04-25T01:32:38.409ZApr 25 01:32:38.373 DEBG [sc] cr1 waiting for prompt
7342026-04-25T01:32:38.409ZApr 25 01:32:38.383 DEBG [sc] cr1: logging in
7352026-04-25T01:32:38.551ZApr 25 01:32:38.539 DEBG [sc] cr1: executing command `sed -i 's/bfdd=no/bfdd=yes/g' /etc/frr/daemons`
7362026-04-25T01:32:40.629ZApr 25 01:32:40.617 DEBG [sc] cr1: starting
7372026-04-25T01:32:40.629ZApr 25 01:32:40.617 DEBG [sc] cr1: connecting to [::1]:64232
7382026-04-25T01:32:40.653ZApr 25 01:32:40.617 DEBG [sc] cr1 waiting for prompt
7392026-04-25T01:32:40.653ZApr 25 01:32:40.628 DEBG [sc] cr1: logging in
7402026-04-25T01:32:40.793ZApr 25 01:32:40.781 DEBG [sc] cr1: executing command `systemctl restart frr`
7412026-04-25T01:32:48.371ZApr 25 01:32:48.358 INFO cr1: executing frr script
7422026-04-25T01:32:48.371Z configure
7432026-04-25T01:32:48.371Z interface enp0s8
7442026-04-25T01:32:48.371Z ip address 10.0.0.2/24
7452026-04-25T01:32:48.371Z ipv6 address fd00:1::2/64
7462026-04-25T01:32:48.371Z no shutdown
7472026-04-25T01:32:48.371Z exit
7482026-04-25T01:32:48.371Z bfd
7492026-04-25T01:32:48.371Z peer 10.0.0.1 local-address 10.0.0.2
7502026-04-25T01:32:48.371Z detect-multiplier 3
7512026-04-25T01:32:48.371Z receive-interval 300
7522026-04-25T01:32:48.371Z transmit-interval 300
7532026-04-25T01:32:48.371Z no shutdown
7542026-04-25T01:32:48.371Z exit
7552026-04-25T01:32:48.371Z peer fd00:1::1 local-address fd00:1::2
7562026-04-25T01:32:48.371Z detect-multiplier 3
7572026-04-25T01:32:48.371Z receive-interval 300
7582026-04-25T01:32:48.371Z transmit-interval 300
7592026-04-25T01:32:48.371Z no shutdown
7602026-04-25T01:32:48.371Z exit
7612026-04-25T01:32:48.371Z exit
7622026-04-25T01:32:48.371Z
7632026-04-25T01:32:48.371ZApr 25 01:32:48.358 DEBG [sc] cr1: starting
7642026-04-25T01:32:48.371ZApr 25 01:32:48.358 DEBG [sc] cr1: connecting to [::1]:64232
7652026-04-25T01:32:48.396ZApr 25 01:32:48.359 DEBG [sc] cr1 waiting for prompt
7662026-04-25T01:32:48.396ZApr 25 01:32:48.370 DEBG [sc] cr1: logging in
7672026-04-25T01:32:48.515ZApr 25 01:32:48.503 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-04-25T01:33:51.833ZApr 25 01:33:51.820 DEBG [sc] ox: starting
7692026-04-25T01:33:51.833ZApr 25 01:33:51.820 DEBG [sc] ox: connecting to [::1]:45992
7702026-04-25T01:33:51.857ZApr 25 01:33:51.821 DEBG [sc] ox waiting for prompt
7712026-04-25T01:33:51.857ZApr 25 01:33:51.831 DEBG [sc] ox: logging in
7722026-04-25T01:33:51.922ZApr 25 01:33:51.910 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
7732026-04-25T01:33:52.287ZApr 25 01:33:52.275 DEBG [sc] ox: starting
7742026-04-25T01:33:52.287ZApr 25 01:33:52.275 DEBG [sc] ox: connecting to [::1]:45992
7752026-04-25T01:33:52.312ZApr 25 01:33:52.276 DEBG [sc] ox waiting for prompt
7762026-04-25T01:33:52.312ZApr 25 01:33:52.287 DEBG [sc] ox: logging in
7772026-04-25T01:33:52.386ZApr 25 01:33:52.374 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7782026-04-25T01:33:53.410ZApr 25 01:33:53.398 DEBG [sc] ox: starting
7792026-04-25T01:33:53.412ZApr 25 01:33:53.398 DEBG [sc] ox: connecting to [::1]:45992
7802026-04-25T01:33:53.436ZApr 25 01:33:53.399 DEBG [sc] ox waiting for prompt
7812026-04-25T01:33:53.436ZApr 25 01:33:53.399 DEBG [sc] ox: logging in
7822026-04-25T01:33:53.489ZApr 25 01:33:53.477 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7832026-04-25T01:33:53.544ZApr 25 01:33:53.532 DEBG [sc] ox: starting
7842026-04-25T01:33:53.544ZApr 25 01:33:53.532 DEBG [sc] ox: connecting to [::1]:45992
7852026-04-25T01:33:53.568ZApr 25 01:33:53.533 DEBG [sc] ox waiting for prompt
7862026-04-25T01:33:53.568ZApr 25 01:33:53.543 DEBG [sc] ox: logging in
7872026-04-25T01:33:53.632ZApr 25 01:33:53.620 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7882026-04-25T01:33:54.011ZApr 25 01:33:53.999 DEBG [sc] ox: starting
7892026-04-25T01:33:54.011ZApr 25 01:33:53.999 DEBG [sc] ox: connecting to [::1]:45992
7902026-04-25T01:33:54.035ZApr 25 01:33:54.000 DEBG [sc] ox waiting for prompt
7912026-04-25T01:33:54.035ZApr 25 01:33:54.011 DEBG [sc] ox: logging in
7922026-04-25T01:33:54.100ZApr 25 01:33:54.088 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
7932026-04-25T01:33:54.155ZApr 25 01:33:54.143 DEBG [sc] ox: starting
7942026-04-25T01:33:54.156ZApr 25 01:33:54.143 DEBG [sc] ox: connecting to [::1]:45992
7952026-04-25T01:33:54.179ZApr 25 01:33:54.144 DEBG [sc] ox waiting for prompt
7962026-04-25T01:33:54.180ZApr 25 01:33:54.154 DEBG [sc] ox: logging in
7972026-04-25T01:33:54.243ZApr 25 01:33:54.231 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
7982026-04-25T01:33:54.298ZApr 25 01:33:54.286 DEBG [sc] ox: starting
7992026-04-25T01:33:54.298ZApr 25 01:33:54.286 DEBG [sc] ox: connecting to [::1]:45992
8002026-04-25T01:33:54.322ZApr 25 01:33:54.287 DEBG [sc] ox waiting for prompt
8012026-04-25T01:33:54.322ZApr 25 01:33:54.297 DEBG [sc] ox: logging in
8022026-04-25T01:33:54.386ZApr 25 01:33:54.373 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.0.1/24 tfportqsfp0_0/v4`
8032026-04-25T01:33:54.993ZApr 25 01:33:54.981 DEBG [sc] ox: starting
8042026-04-25T01:33:54.993ZApr 25 01:33:54.981 DEBG [sc] ox: connecting to [::1]:45992
8052026-04-25T01:33:55.017ZApr 25 01:33:54.982 DEBG [sc] ox waiting for prompt
8062026-04-25T01:33:55.017ZApr 25 01:33:54.992 DEBG [sc] ox: logging in
8072026-04-25T01:33:55.082ZApr 25 01:33:55.070 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v4 -p -o addr`
8082026-04-25T01:33:55.137ZApr 25 01:33:55.125 DEBG [sc] ox: starting
8092026-04-25T01:33:55.137ZApr 25 01:33:55.125 DEBG [sc] ox: connecting to [::1]:45992
8102026-04-25T01:33:55.162ZApr 25 01:33:55.126 DEBG [sc] ox waiting for prompt
8112026-04-25T01:33:55.162ZApr 25 01:33:55.136 DEBG [sc] ox: logging in
8122026-04-25T01:33:55.226ZApr 25 01:33:55.213 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:1::1/64 tfportqsfp0_0/v6`
8132026-04-25T01:33:55.738ZApr 25 01:33:55.726 DEBG [sc] ox: starting
8142026-04-25T01:33:55.738ZApr 25 01:33:55.726 DEBG [sc] ox: connecting to [::1]:45992
8152026-04-25T01:33:55.762ZApr 25 01:33:55.727 DEBG [sc] ox waiting for prompt
8162026-04-25T01:33:55.762ZApr 25 01:33:55.737 DEBG [sc] ox: logging in
8172026-04-25T01:33:55.827ZApr 25 01:33:55.815 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v6 -p -o addr`
8182026-04-25T01:33:55.882ZApr 25 01:33:55.870 DEBG [sc] ox: starting
8192026-04-25T01:33:55.882ZApr 25 01:33:55.870 DEBG [sc] ox: connecting to [::1]:45992
8202026-04-25T01:33:55.906ZApr 25 01:33:55.871 DEBG [sc] ox waiting for prompt
8212026-04-25T01:33:55.906ZApr 25 01:33:55.881 DEBG [sc] ox: logging in
8222026-04-25T01:33:55.970ZApr 25 01:33:55.958 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
8232026-04-25T01:33:56.026ZApr 25 01:33:56.014 DEBG [sc] ox: starting
8242026-04-25T01:33:56.026ZApr 25 01:33:56.014 DEBG [sc] ox: connecting to [::1]:45992
8252026-04-25T01:33:56.050ZApr 25 01:33:56.014 DEBG [sc] ox waiting for prompt
8262026-04-25T01:33:56.050ZApr 25 01:33:56.025 DEBG [sc] ox: logging in
8272026-04-25T01:33:56.113ZApr 25 01:33:56.102 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
8282026-04-25T01:33:56.170ZApr 25 01:33:56.157 DEBG [sc] ox: starting
8292026-04-25T01:33:56.170ZApr 25 01:33:56.157 DEBG [sc] ox: connecting to [::1]:45992
8302026-04-25T01:33:56.194ZApr 25 01:33:56.158 DEBG [sc] ox waiting for prompt
8312026-04-25T01:33:56.194ZApr 25 01:33:56.169 DEBG [sc] ox: logging in
8322026-04-25T01:33:56.258ZApr 25 01:33:56.246 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.1.1/24 tfportqsfp1_0/v4`
8332026-04-25T01:33:56.859ZApr 25 01:33:56.847 DEBG [sc] ox: starting
8342026-04-25T01:33:56.859ZApr 25 01:33:56.847 DEBG [sc] ox: connecting to [::1]:45992
8352026-04-25T01:33:56.883ZApr 25 01:33:56.847 DEBG [sc] ox waiting for prompt
8362026-04-25T01:33:56.883ZApr 25 01:33:56.858 DEBG [sc] ox: logging in
8372026-04-25T01:33:56.947ZApr 25 01:33:56.935 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v4 -p -o addr`
8382026-04-25T01:33:57.013ZApr 25 01:33:57.001 DEBG [sc] ox: starting
8392026-04-25T01:33:57.013ZApr 25 01:33:57.001 DEBG [sc] ox: connecting to [::1]:45992
8402026-04-25T01:33:57.037ZApr 25 01:33:57.002 DEBG [sc] ox waiting for prompt
8412026-04-25T01:33:57.037ZApr 25 01:33:57.012 DEBG [sc] ox: logging in
8422026-04-25T01:33:57.102ZApr 25 01:33:57.090 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:2::1/64 tfportqsfp1_0/v6`
8432026-04-25T01:33:57.616ZApr 25 01:33:57.603 DEBG [sc] ox: starting
8442026-04-25T01:33:57.616ZApr 25 01:33:57.603 DEBG [sc] ox: connecting to [::1]:45992
8452026-04-25T01:33:57.640ZApr 25 01:33:57.604 DEBG [sc] ox waiting for prompt
8462026-04-25T01:33:57.640ZApr 25 01:33:57.614 DEBG [sc] ox: logging in
8472026-04-25T01:33:57.703ZApr 25 01:33:57.691 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v6 -p -o addr`
8482026-04-25T01:33:57.758ZApr 25 01:33:57.746 DEBG [sc] ox: starting
8492026-04-25T01:33:57.758ZApr 25 01:33:57.746 DEBG [sc] ox: connecting to [::1]:45992
8502026-04-25T01:33:57.782ZApr 25 01:33:57.746 DEBG [sc] ox waiting for prompt
8512026-04-25T01:33:57.782ZApr 25 01:33:57.757 DEBG [sc] ox: logging in
8522026-04-25T01:33:57.847ZApr 25 01:33:57.834 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
8532026-04-25T01:33:57.901ZApr 25 01:33:57.889 DEBG [sc] ox: starting
8542026-04-25T01:33:57.901ZApr 25 01:33:57.889 DEBG [sc] ox: connecting to [::1]:45992
8552026-04-25T01:33:57.925ZApr 25 01:33:57.890 DEBG [sc] ox waiting for prompt
8562026-04-25T01:33:57.925ZApr 25 01:33:57.900 DEBG [sc] ox: logging in
8572026-04-25T01:33:57.990ZApr 25 01:33:57.978 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
8582026-04-25T01:33:58.051ZApr 25 01:33:58.039 INFO installing static v4 route 192.168.100.0/24
8592026-04-25T01:33:58.075ZApr 25 01:33:58.040 INFO installing static v6 route fd01::/64
8602026-04-25T01:33:58.075ZApr 25 01:33:58.041 INFO adding BFD peers for cr1 and cr2 (dual-stack)
8612026-04-25T01:33:58.075ZApr 25 01:33:58.044 INFO phase 1: both peers up
8622026-04-25T01:33:59.059ZApr 25 01:33:59.047 INFO cr1: executing frr script show bfd peers json
8632026-04-25T01:33:59.059ZApr 25 01:33:59.047 DEBG [sc] cr1: starting
8642026-04-25T01:33:59.059ZApr 25 01:33:59.047 DEBG [sc] cr1: connecting to [::1]:64232
8652026-04-25T01:33:59.083ZApr 25 01:33:59.048 DEBG [sc] cr1 waiting for prompt
8662026-04-25T01:33:59.083ZApr 25 01:33:59.059 DEBG [sc] cr1: logging in
8672026-04-25T01:33:59.399ZApr 25 01:33:59.387 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8682026-04-25T01:34:01.539ZApr 25 01:34:01.527 INFO cr1: executing frr script show bfd peers json
8692026-04-25T01:34:01.539ZApr 25 01:34:01.527 DEBG [sc] cr1: starting
8702026-04-25T01:34:01.539ZApr 25 01:34:01.527 DEBG [sc] cr1: connecting to [::1]:64232
8712026-04-25T01:34:01.564ZApr 25 01:34:01.528 DEBG [sc] cr1 waiting for prompt
8722026-04-25T01:34:01.564ZApr 25 01:34:01.538 DEBG [sc] cr1: logging in
8732026-04-25T01:34:01.693ZApr 25 01:34:01.681 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8742026-04-25T01:34:03.828ZApr 25 01:34:03.816 INFO cr2: executing eos script show bfd peers | json
8752026-04-25T01:34:03.828ZApr 25 01:34:03.816 DEBG [sc] cr2: starting
8762026-04-25T01:34:03.828ZApr 25 01:34:03.816 DEBG [sc] cr2: connecting to [::1]:45464
8772026-04-25T01:34:03.852ZApr 25 01:34:03.817 DEBG [sc] cr2 waiting for prompt
8782026-04-25T01:34:03.852ZApr 25 01:34:03.827 DEBG [sc] cr2: logging in
8792026-04-25T01:34:04.178ZApr 25 01:34:04.166 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8802026-04-25T01:34:06.538ZApr 25 01:34:06.524 INFO cr2: executing eos script show bfd peers | json
8812026-04-25T01:34:06.538ZApr 25 01:34:06.524 DEBG [sc] cr2: starting
8822026-04-25T01:34:06.538ZApr 25 01:34:06.525 DEBG [sc] cr2: connecting to [::1]:45464
8832026-04-25T01:34:06.563ZApr 25 01:34:06.526 DEBG [sc] cr2 waiting for prompt
8842026-04-25T01:34:06.563ZApr 25 01:34:06.535 DEBG [sc] cr2: logging in
8852026-04-25T01:34:06.668ZApr 25 01:34:06.656 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8862026-04-25T01:34:09.008ZApr 25 01:34:08.996 INFO phase 2: pause bfdd on cr1
8872026-04-25T01:34:09.009ZApr 25 01:34:08.996 INFO cr1: pausing frr bfdd
8882026-04-25T01:34:09.009ZApr 25 01:34:08.996 DEBG [sc] cr1: starting
8892026-04-25T01:34:09.009ZApr 25 01:34:08.996 DEBG [sc] cr1: connecting to [::1]:64232
8902026-04-25T01:34:09.033ZApr 25 01:34:08.997 DEBG [sc] cr1 waiting for prompt
8912026-04-25T01:34:09.033ZApr 25 01:34:09.008 DEBG [sc] cr1: logging in
8922026-04-25T01:34:09.163ZApr 25 01:34:09.151 DEBG [sc] cr1: executing command `pkill -STOP bfdd`
8932026-04-25T01:34:11.265ZApr 25 01:34:11.252 INFO cr2: executing eos script show bfd peers | json
8942026-04-25T01:34:11.265ZApr 25 01:34:11.252 DEBG [sc] cr2: starting
8952026-04-25T01:34:11.265ZApr 25 01:34:11.252 DEBG [sc] cr2: connecting to [::1]:45464
8962026-04-25T01:34:11.289ZApr 25 01:34:11.253 DEBG [sc] cr2 waiting for prompt
8972026-04-25T01:34:11.289ZApr 25 01:34:11.263 DEBG [sc] cr2: logging in
8982026-04-25T01:34:11.430ZApr 25 01:34:11.418 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8992026-04-25T01:34:13.757ZApr 25 01:34:13.745 INFO cr2: executing eos script show bfd peers | json
9002026-04-25T01:34:13.757ZApr 25 01:34:13.745 DEBG [sc] cr2: starting
9012026-04-25T01:34:13.757ZApr 25 01:34:13.745 DEBG [sc] cr2: connecting to [::1]:45464
9022026-04-25T01:34:13.806ZApr 25 01:34:13.746 DEBG [sc] cr2 waiting for prompt
9032026-04-25T01:34:13.831ZApr 25 01:34:13.755 DEBG [sc] cr2: logging in
9042026-04-25T01:34:13.901ZApr 25 01:34:13.889 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9052026-04-25T01:34:16.244ZApr 25 01:34:16.232 INFO phase 3: pause ceos on cr2
9062026-04-25T01:34:16.244ZApr 25 01:34:16.232 INFO cr2: pausing ceos
9072026-04-25T01:34:16.244ZApr 25 01:34:16.232 DEBG [sc] cr2: starting
9082026-04-25T01:34:16.244ZApr 25 01:34:16.232 DEBG [sc] cr2: connecting to [::1]:45464
9092026-04-25T01:34:16.268ZApr 25 01:34:16.232 DEBG [sc] cr2 waiting for prompt
9102026-04-25T01:34:16.268ZApr 25 01:34:16.241 DEBG [sc] cr2: logging in
9112026-04-25T01:34:16.375ZApr 25 01:34:16.363 DEBG [sc] cr2: executing command `docker pause ceos`
9122026-04-25T01:34:18.484ZApr 25 01:34:18.472 INFO phase 4: resume bfdd on cr1
9132026-04-25T01:34:18.484ZApr 25 01:34:18.472 INFO cr1: resuming frr bfdd
9142026-04-25T01:34:18.484ZApr 25 01:34:18.472 DEBG [sc] cr1: starting
9152026-04-25T01:34:18.484ZApr 25 01:34:18.472 DEBG [sc] cr1: connecting to [::1]:64232
9162026-04-25T01:34:18.509ZApr 25 01:34:18.472 DEBG [sc] cr1 waiting for prompt
9172026-04-25T01:34:18.509ZApr 25 01:34:18.484 DEBG [sc] cr1: logging in
9182026-04-25T01:34:18.629ZApr 25 01:34:18.616 DEBG [sc] cr1: executing command `pkill -CONT bfdd`
9192026-04-25T01:34:20.716ZApr 25 01:34:20.703 INFO cr1: executing frr script show bfd peers json
9202026-04-25T01:34:20.716ZApr 25 01:34:20.704 DEBG [sc] cr1: starting
9212026-04-25T01:34:20.716ZApr 25 01:34:20.704 DEBG [sc] cr1: connecting to [::1]:64232
9222026-04-25T01:34:20.741ZApr 25 01:34:20.704 DEBG [sc] cr1 waiting for prompt
9232026-04-25T01:34:20.741ZApr 25 01:34:20.713 DEBG [sc] cr1: logging in
9242026-04-25T01:34:20.846ZApr 25 01:34:20.834 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9252026-04-25T01:34:22.974ZApr 25 01:34:22.962 INFO cr1: executing frr script show bfd peers json
9262026-04-25T01:34:22.974ZApr 25 01:34:22.962 DEBG [sc] cr1: starting
9272026-04-25T01:34:22.974ZApr 25 01:34:22.962 DEBG [sc] cr1: connecting to [::1]:64232
9282026-04-25T01:34:22.999ZApr 25 01:34:22.963 DEBG [sc] cr1 waiting for prompt
9292026-04-25T01:34:22.999ZApr 25 01:34:22.973 DEBG [sc] cr1: logging in
9302026-04-25T01:34:23.118ZApr 25 01:34:23.106 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9312026-04-25T01:34:25.260ZApr 25 01:34:25.248 INFO phase 5: unpause ceos on cr2
9322026-04-25T01:34:25.260ZApr 25 01:34:25.248 INFO cr2: unpausing ceos
9332026-04-25T01:34:25.261ZApr 25 01:34:25.248 DEBG [sc] cr2: starting
9342026-04-25T01:34:25.261ZApr 25 01:34:25.248 DEBG [sc] cr2: connecting to [::1]:45464
9352026-04-25T01:34:25.285ZApr 25 01:34:25.249 DEBG [sc] cr2 waiting for prompt
9362026-04-25T01:34:25.285ZApr 25 01:34:25.260 DEBG [sc] cr2: logging in
9372026-04-25T01:34:25.438ZApr 25 01:34:25.426 DEBG [sc] cr2: executing command `docker unpause ceos`
9382026-04-25T01:34:27.560ZApr 25 01:34:27.548 INFO cr1: executing frr script show bfd peers json
9392026-04-25T01:34:27.560ZApr 25 01:34:27.548 DEBG [sc] cr1: starting
9402026-04-25T01:34:27.560ZApr 25 01:34:27.548 DEBG [sc] cr1: connecting to [::1]:64232
9412026-04-25T01:34:27.585ZApr 25 01:34:27.548 DEBG [sc] cr1 waiting for prompt
9422026-04-25T01:34:27.585ZApr 25 01:34:27.559 DEBG [sc] cr1: logging in
9432026-04-25T01:34:27.703ZApr 25 01:34:27.691 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9442026-04-25T01:34:29.842ZApr 25 01:34:29.830 INFO cr1: executing frr script show bfd peers json
9452026-04-25T01:34:29.842ZApr 25 01:34:29.830 DEBG [sc] cr1: starting
9462026-04-25T01:34:29.842ZApr 25 01:34:29.830 DEBG [sc] cr1: connecting to [::1]:64232
9472026-04-25T01:34:29.867ZApr 25 01:34:29.831 DEBG [sc] cr1 waiting for prompt
9482026-04-25T01:34:29.867ZApr 25 01:34:29.841 DEBG [sc] cr1: logging in
9492026-04-25T01:34:29.985ZApr 25 01:34:29.973 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9502026-04-25T01:34:32.122ZApr 25 01:34:32.110 INFO cr2: executing eos script show bfd peers | json
9512026-04-25T01:34:32.122ZApr 25 01:34:32.110 DEBG [sc] cr2: starting
9522026-04-25T01:34:32.122ZApr 25 01:34:32.110 DEBG [sc] cr2: connecting to [::1]:45464
9532026-04-25T01:34:32.147ZApr 25 01:34:32.111 DEBG [sc] cr2 waiting for prompt
9542026-04-25T01:34:32.147ZApr 25 01:34:32.122 DEBG [sc] cr2: logging in
9552026-04-25T01:34:32.257ZApr 25 01:34:32.244 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9562026-04-25T01:34:34.586ZApr 25 01:34:34.574 INFO cr2: executing eos script show bfd peers | json
9572026-04-25T01:34:34.586ZApr 25 01:34:34.574 DEBG [sc] cr2: starting
9582026-04-25T01:34:34.586ZApr 25 01:34:34.574 DEBG [sc] cr2: connecting to [::1]:45464
9592026-04-25T01:34:34.611ZApr 25 01:34:34.575 DEBG [sc] cr2 waiting for prompt
9602026-04-25T01:34:34.611ZApr 25 01:34:34.585 DEBG [sc] cr2: logging in
9612026-04-25T01:34:34.718ZApr 25 01:34:34.706 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9622026-04-25T01:34:37.075ZApr 25 01:34:37.062 INFO trio bfd static routing test passed 🎉
9632026-04-25T01:34:37.075ZApr 25 01:34:37.063 INFO destroying runner for deployment mgtriobfd
9642026-04-25T01:34:37.075ZApr 25 01:34:37.063 INFO destroying deployment mgtriobfd
9652026-04-25T01:34:37.075ZApr 25 01:34:37.063 INFO destroying nodes
9662026-04-25T01:34:37.176ZApr 25 01:34:37.164 INFO destroying links
9672026-04-25T01:34:37.176ZApr 25 01:34:37.164 INFO destroying link mgtriobfd_ox_sn_vnic0
9682026-04-25T01:34:37.200ZApr 25 01:34:37.166 INFO destroying link mgtriobfd_ox_sn_sim0
9692026-04-25T01:34:37.200ZApr 25 01:34:37.167 INFO destroying link mgtriobfd_cr1_vn_vnic0
9702026-04-25T01:34:38.182ZApr 25 01:34:38.170 INFO destroying link mgtriobfd_cr1_vn_sim0
9712026-04-25T01:34:38.207ZApr 25 01:34:38.172 INFO destroying link mgtriobfd_ox_sn_vnic1
9722026-04-25T01:34:38.207ZApr 25 01:34:38.173 INFO destroying link mgtriobfd_ox_sn_sim1
9732026-04-25T01:34:38.207ZApr 25 01:34:38.174 INFO destroying link mgtriobfd_cr2_vn_vnic0
9742026-04-25T01:34:38.207ZApr 25 01:34:38.175 INFO destroying link mgtriobfd_cr2_vn_sim0
9752026-04-25T01:34:38.207ZApr 25 01:34:38.176 INFO destroying external links
9762026-04-25T01:34:38.207ZApr 25 01:34:38.176 INFO destroying external link mgtriobfd_ox_vn_vnic2
9772026-04-25T01:34:38.207ZApr 25 01:34:38.177 INFO destroying external link mgtriobfd_cr1_vn_vnic1
9782026-04-25T01:34:38.207ZApr 25 01:34:38.178 INFO destroying external link mgtriobfd_cr2_vn_vnic1
9792026-04-25T01:34:38.208ZApr 25 01:34:38.180 INFO destroying images
9802026-04-25T01:34:38.666ZApr 25 01:34:38.654 INFO destroying workspace at .falcon
9812026-04-25T01:34:38.691Zprocess exited: duration 685326 ms, exit code 0
 
9822026-04-25T01:34:38.743Zfound 0 output files