01KRQD3B1AP75BP2GWJ958VYQ4: falcon

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

Buildomat Job: 01KRQD41RW06HSCVSXB19Z7K1Q

Tags:

Output:

SEQ GLOBAL TIME DETAILS
12026-05-16T03:41:28.262Zjob dependencies complete; ready to run (waiting for 15 m 11 s)
22026-05-16T04:05:31.163Zjob assigned to worker 01KRQF5Z9PVSMAV7FTCXA027V2 [factory edgar, gimlet/BRM42220060/571] (queued for 24 m 2 s)
32026-05-16T04:05:31.762Zdownloading input: /input/build/work/debug/ddmadm
42026-05-16T04:05:55.134Zdownloaded input: /input/build/work/debug/ddmadm
52026-05-16T04:05:55.159Zdownloading input: /input/build-interop/work/testbed.tar.gz
62026-05-16T04:06:07.565Zdownloaded input: /input/build-interop/work/testbed.tar.gz
72026-05-16T04:06:07.565Zdownloading input: /input/build-interop/work/dhcp-server
82026-05-16T04:06:10.255Zdownloaded input: /input/build-interop/work/dhcp-server
92026-05-16T04:06:10.280Zdownloading input: /input/build/work/debug/ddmd
102026-05-16T04:06:37.031Zdownloaded input: /input/build/work/debug/ddmd
112026-05-16T04:06:37.031Zdownloading input: /input/build/work/debug/mgadm
122026-05-16T04:07:03.437Zdownloaded input: /input/build/work/debug/mgadm
132026-05-16T04:07:03.437Zdownloading input: /input/build/work/debug/mgd
142026-05-16T04:07:34.198Zdownloaded input: /input/build/work/debug/mgd
152026-05-16T04:07:34.223Zdownloading input: /input/build/work/release/ddmadm
162026-05-16T04:07:36.387Zdownloaded input: /input/build/work/release/ddmadm
172026-05-16T04:07:36.387Zdownloading input: /input/build/work/release/ddmd
182026-05-16T04:07:40.395Zdownloaded input: /input/build/work/release/ddmd
192026-05-16T04:07:40.396Zdownloading input: /input/build/work/release/falcon-lab
202026-05-16T04:07:42.439Zdownloaded input: /input/build/work/release/falcon-lab
212026-05-16T04:07:42.440Zdownloading input: /input/build/work/release/mgadm
222026-05-16T04:07:45.152Zdownloaded input: /input/build/work/release/mgadm
232026-05-16T04:07:45.152Zdownloading input: /input/build/work/release/mgd
242026-05-16T04:07:48.472Zdownloaded input: /input/build/work/release/mgd
 
252026-05-16T04:07:48.472Zstarting task 0: "setup"
262026-05-16T04:07:48.497Z++ uname -s
272026-05-16T04:07:48.497Z+ kern=SunOS
282026-05-16T04:07:48.497Z+ build_user=build
292026-05-16T04:07:48.497Z+ build_uid=12345
302026-05-16T04:07:48.497Z+ work_dir=/work
312026-05-16T04:07:48.497Z+ input_dir=/input
322026-05-16T04:07:48.497Z+ [[ 0 == 12345 ]]
332026-05-16T04:07:48.497Z+ case "$kern" in
342026-05-16T04:07:48.497Z+ groupadd -g 12345 build
352026-05-16T04:07:48.522Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
362026-05-16T04:07:50.510Z+ zfs create -o mountpoint=/work rpool/work
372026-05-16T04:07:51.529Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
382026-05-16T04:07:51.555Z+ home_fs=
392026-05-16T04:07:51.555Z+ [[ '' == autofs ]]
402026-05-16T04:07:51.555Z+ mkdir -p /home/build
412026-05-16T04:07:51.555Z+ chown build:build /home/build /work
422026-05-16T04:07:52.543Z+ chmod 0700 /home/build /work
432026-05-16T04:07:52.569Zprocess exited: duration 4074 ms, exit code 0
 
442026-05-16T04:07:52.618Zstarting task 1: "authentication"
452026-05-16T04:07:52.714Zprocess exited: duration 95 ms, exit code 0
 
462026-05-16T04:07:52.773Zstarting task 2: "build"
472026-05-16T04:07:53.273Z+ set -e
482026-05-16T04:07:53.273Z+ banner zpool
492026-05-16T04:07:53.274Z
502026-05-16T04:07:53.274Z ###### ##### #### #### #
512026-05-16T04:07:53.274Z # # # # # # # #
522026-05-16T04:07:53.274Z # # # # # # # #
532026-05-16T04:07:53.274Z # ##### # # # # #
542026-05-16T04:07:53.274Z # # # # # # #
552026-05-16T04:07:53.274Z ###### # #### #### ######
562026-05-16T04:07:53.274Z
572026-05-16T04:07:53.274Z++ pfexec diskinfo -pH
582026-05-16T04:07:53.274Z++ sort -k8 -n -r
592026-05-16T04:07:53.274Z++ head -1
602026-05-16T04:07:53.274Z++ awk '{print $2}'
612026-05-16T04:07:53.274Z+ DISK=c9t0014EE81000BC57Cd0
622026-05-16T04:07:53.274Z+ export DISK
632026-05-16T04:07:53.274Z+ pfexec zpool create -o ashift=12 -f cpool c9t0014EE81000BC57Cd0
642026-05-16T04:07:53.274Z+ pfexec zfs create -o mountpoint=/ci cpool/ci
652026-05-16T04:07:53.274Z++ curl -s http://catacomb.eng.oxide.computer:12346/trim-me
662026-05-16T04:07:53.274Z+ [[ true =~ true ]]
672026-05-16T04:07:53.274Z+ pfexec zpool trim cpool
682026-05-16T04:07:53.274Z++ zpool status -t cpool
692026-05-16T04:07:53.274Z+ [[ ! pool: cpool
702026-05-16T04:07:53.275Z state: ONLINE
712026-05-16T04:07:53.275Z scan: none requested
722026-05-16T04:07:53.275Zconfig:
732026-05-16T04:07:53.275Z
742026-05-16T04:07:53.275Z NAME STATE READ WRITE CKSUM
752026-05-16T04:07:53.275Z cpool ONLINE 0 0 0
762026-05-16T04:07:53.275Z c9t0014EE81000BC57Cd0 ONLINE 0 0 0 (1% trimmed, started at May 16, 2026 at 04:07:53 AM UTC)
772026-05-16T04:07:53.275Z
782026-05-16T04:07:53.275Zerrors: No known data errors =~ 100% ]]
792026-05-16T04:07:53.275Z+ sleep 10
802026-05-16T04:08:03.137Z++ zpool status -t cpool
812026-05-16T04:08:03.162Z+ [[ ! pool: cpool
822026-05-16T04:08:03.162Z state: ONLINE
832026-05-16T04:08:03.162Z scan: none requested
842026-05-16T04:08:03.162Zconfig:
852026-05-16T04:08:03.162Z
862026-05-16T04:08:03.162Z NAME STATE READ WRITE CKSUM
872026-05-16T04:08:03.162Z cpool ONLINE 0 0 0
882026-05-16T04:08:03.162Z c9t0014EE81000BC57Cd0 ONLINE 0 0 0 (69% trimmed, started at May 16, 2026 at 04:07:53 AM UTC)
892026-05-16T04:08:03.162Z
902026-05-16T04:08:03.163Zerrors: No known data errors =~ 100% ]]
912026-05-16T04:08:03.163Z+ sleep 10
922026-05-16T04:08:13.152Z++ zpool status -t cpool
932026-05-16T04:08:13.176Z+ [[ ! pool: cpool
942026-05-16T04:08:13.176Z state: ONLINE
952026-05-16T04:08:13.176Z scan: none requested
962026-05-16T04:08:13.176Zconfig:
972026-05-16T04:08:13.176Z
982026-05-16T04:08:13.176Z NAME STATE READ WRITE CKSUM
992026-05-16T04:08:13.176Z cpool ONLINE 0 0 0
1002026-05-16T04:08:13.176Z c9t0014EE81000BC57Cd0 ONLINE 0 0 0 (100% trimmed, completed at May 16, 2026 at 04:08:07 AM UTC)
1012026-05-16T04:08:13.176Z
1022026-05-16T04:08:13.176Zerrors: No known data errors =~ 100% ]]
1032026-05-16T04:08:13.176Z+ pfexec chown 12345 /ci
1042026-05-16T04:08:13.176Z+ cd /ci
1052026-05-16T04:08:13.176Z+ export FALCON_DATASET=cpool/falcon
1062026-05-16T04:08:13.177Z+ FALCON_DATASET=cpool/falcon
1072026-05-16T04:08:13.177Z+ banner setup
1082026-05-16T04:08:13.177Z
1092026-05-16T04:08:13.177Z #### ###### ##### # # #####
1102026-05-16T04:08:13.177Z # # # # # # #
1112026-05-16T04:08:13.177Z #### ##### # # # # #
1122026-05-16T04:08:13.177Z # # # # # #####
1132026-05-16T04:08:13.177Z # # # # # # #
1142026-05-16T04:08:13.177Z #### ###### # #### #
1152026-05-16T04:08:13.177Z
1162026-05-16T04:08:13.177Z+ cp /input/build-interop/work/dhcp-server .
1172026-05-16T04:08:13.524Z+ cp /input/build/work/release/falcon-lab .
1182026-05-16T04:08:13.556Z+ cp /input/build/work/release/mgd .
1192026-05-16T04:08:13.620Z+ cp /input/build/work/release/ddmd .
1202026-05-16T04:08:13.675Z+ chmod +x dhcp-server falcon-lab mgd ddmd
1212026-05-16T04:08:13.699Z+ mkdir -p cargo-bay
1222026-05-16T04:08:13.699Z+ mv mgd cargo-bay/
1232026-05-16T04:08:13.699Z+ mv ddmd cargo-bay/
1242026-05-16T04:08:13.699Z+ export EXT_INTERFACE=igb0
1252026-05-16T04:08:13.699Z+ EXT_INTERFACE=igb0
1262026-05-16T04:08:13.699Z++ bmat address ls -f extra -Ho first
1272026-05-16T04:08:13.723Z+ first=10.151.7.164
1282026-05-16T04:08:13.746Z++ bmat address ls -f extra -Ho last
1292026-05-16T04:08:13.746Z+ last=10.151.7.227
1302026-05-16T04:08:13.770Z++ bmat address ls -f extra -Ho gateway
1312026-05-16T04:08:13.770Z+ gw=10.151.7.1
1322026-05-16T04:08:13.795Z++ ipadm show-addr igb0/dhcp -po ADDR
1332026-05-16T04:08:13.795Z++ sed 's#/.*##g'
1342026-05-16T04:08:13.795Z+ server=10.151.7.100
1352026-05-16T04:08:13.795Z+ RUST_LOG=debug
1362026-05-16T04:08:13.795Z+ pfexec ./falcon-lab run trio-unnumbered
1372026-05-16T04:08:13.795Z+ pfexec ./dhcp-server 10.151.7.164 10.151.7.227 10.151.7.1 10.151.7.100
1382026-05-16T04:08:13.819ZMay 16 04:08:13.792 DEBG using default route interface igb0
1392026-05-16T04:08:13.819ZMay 16 04:08:13.792 DEBG using default route interface igb0
1402026-05-16T04:08:13.819ZMay 16 04:08:13.792 DEBG using default route interface igb0
1412026-05-16T04:08:13.819ZMay 16 04:08:13.792 INFO launching runner: deployment(mgtriou) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
1422026-05-16T04:08:13.819ZMay 16 04:08:13.792 INFO starting preflight for deployment mgtriou
1432026-05-16T04:08:13.819ZMay 16 04:08:13.792 INFO propolis-server binary not found
1442026-05-16T04:08:13.819ZMay 16 04:08:13.792 INFO downloading propolis server rev 36f20be9bb4c3b362029237f5feb6377c982395f, writing to .falcon/bin/propolis-server
1452026-05-16T04:08:17.742ZMay 16 04:08:17.729 INFO ovmf fd not found
1462026-05-16T04:08:17.742ZMay 16 04:08:17.729 INFO downloading ovmf
1472026-05-16T04:08:18.124ZMay 16 04:08:18.112 INFO base image for helios-2.9 does not exist, attempting to install
1482026-05-16T04:08:18.124ZMay 16 04:08:18.112 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/helios-2.9_0.raw.xz
1492026-05-16T04:08:47.695ZMay 16 04:08:47.683 INFO extracting image to /tmp/helios-2.9_0.raw
1502026-05-16T04:09:21.190ZMay 16 04:09:21.177 INFO creating zvol cpool/falcon/img/helios-2.9 of size 4508880896
1512026-05-16T04:09:21.243ZMay 16 04:09:21.231 INFO copying image data to zvol
1522026-05-16T04:09:31.893ZMay 16 04:09:31.881 INFO creating zfs snapshot cpool/falcon/img/helios-2.9@base
1532026-05-16T04:09:35.255ZMay 16 04:09:35.243 INFO base image for debian-13.2 does not exist, attempting to install
1542026-05-16T04:09:35.255ZMay 16 04:09:35.243 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz
1552026-05-16T04:09:56.250ZMay 16 04:09:56.238 INFO extracting image to /tmp/debian-13.2_0.raw
1562026-05-16T04:10:17.064ZMay 16 04:10:17.050 INFO creating zvol cpool/falcon/img/debian-13.2 of size 3221229568
1572026-05-16T04:10:17.089ZMay 16 04:10:17.077 INFO copying image data to zvol
1582026-05-16T04:10:23.299ZMay 16 04:10:23.287 INFO creating zfs snapshot cpool/falcon/img/debian-13.2@base
1592026-05-16T04:10:26.862ZMay 16 04:10:26.850 INFO base image for eos-4.35 does not exist, attempting to install
1602026-05-16T04:10:26.862ZMay 16 04:10:26.850 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz
1612026-05-16T04:11:10.376ZMay 16 04:11:10.365 INFO extracting image to /tmp/eos-4.35_0.raw
1622026-05-16T04:12:33.453ZMay 16 04:12:33.440 INFO creating zvol cpool/falcon/img/eos-4.35 of size 21474840576
1632026-05-16T04:12:33.478ZMay 16 04:12:33.466 INFO copying image data to zvol
1642026-05-16T04:13:20.995ZMay 16 04:13:20.983 INFO creating zfs snapshot cpool/falcon/img/eos-4.35@base
1652026-05-16T04:13:24.459ZMay 16 04:13:24.447 INFO creating links
1662026-05-16T04:13:24.459ZMay 16 04:13:24.447 DEBG destroying link mgtriou_ox_sn_vnic0
1672026-05-16T04:13:24.483ZMay 16 04:13:24.447 DEBG destroying link mgtriou_ox_sn_sim0
1682026-05-16T04:13:24.483ZMay 16 04:13:24.447 INFO creating simnet link 'mgtriou_ox_sn_sim0'
1692026-05-16T04:13:24.483ZMay 16 04:13:24.449 INFO creating vnic link 'mgtriou_ox_sn_vnic0'
1702026-05-16T04:13:24.483ZMay 16 04:13:24.457 DEBG link pair created
1712026-05-16T04:13:24.483ZMay 16 04:13:24.457 DEBG destroying link mgtriou_cr1_vn_vnic0
1722026-05-16T04:13:24.483ZMay 16 04:13:24.457 DEBG destroying link mgtriou_cr1_vn_sim0
1732026-05-16T04:13:24.483ZMay 16 04:13:24.457 INFO creating simnet link 'mgtriou_cr1_vn_sim0'
1742026-05-16T04:13:24.483ZMay 16 04:13:24.459 INFO creating vnic link 'mgtriou_cr1_vn_vnic0'
1752026-05-16T04:13:24.483ZMay 16 04:13:24.465 DEBG link pair created
1762026-05-16T04:13:24.483ZMay 16 04:13:24.465 DEBG destroying link mgtriou_ox_sn_vnic1
1772026-05-16T04:13:24.483ZMay 16 04:13:24.465 DEBG destroying link mgtriou_ox_sn_sim1
1782026-05-16T04:13:24.483ZMay 16 04:13:24.465 INFO creating simnet link 'mgtriou_ox_sn_sim1'
1792026-05-16T04:13:24.483ZMay 16 04:13:24.467 INFO creating vnic link 'mgtriou_ox_sn_vnic1'
1802026-05-16T04:13:24.508ZMay 16 04:13:24.473 DEBG link pair created
1812026-05-16T04:13:24.508ZMay 16 04:13:24.473 DEBG destroying link mgtriou_cr2_vn_vnic0
1822026-05-16T04:13:24.508ZMay 16 04:13:24.473 DEBG destroying link mgtriou_cr2_vn_sim0
1832026-05-16T04:13:24.508ZMay 16 04:13:24.473 INFO creating simnet link 'mgtriou_cr2_vn_sim0'
1842026-05-16T04:13:24.508ZMay 16 04:13:24.475 INFO creating vnic link 'mgtriou_cr2_vn_vnic0'
1852026-05-16T04:13:24.508ZMay 16 04:13:24.482 DEBG link pair created
1862026-05-16T04:13:24.508ZMay 16 04:13:24.482 INFO creating external links
1872026-05-16T04:13:24.508ZMay 16 04:13:24.482 DEBG destroying external link mgtriou_ox_vn_vnic2
1882026-05-16T04:13:24.508ZMay 16 04:13:24.482 INFO creating external link mgtriou_ox_vn_vnic2
1892026-05-16T04:13:24.508ZMay 16 04:13:24.485 DEBG external link mgtriou_ox_vn_vnic2@igb0 created
1902026-05-16T04:13:24.508ZMay 16 04:13:24.485 DEBG destroying external link mgtriou_cr1_vn_vnic1
1912026-05-16T04:13:24.508ZMay 16 04:13:24.485 INFO creating external link mgtriou_cr1_vn_vnic1
1922026-05-16T04:13:24.508ZMay 16 04:13:24.486 DEBG external link mgtriou_cr1_vn_vnic1@igb0 created
1932026-05-16T04:13:24.508ZMay 16 04:13:24.486 DEBG destroying external link mgtriou_cr2_vn_vnic1
1942026-05-16T04:13:24.508ZMay 16 04:13:24.486 INFO creating external link mgtriou_cr2_vn_vnic1
1952026-05-16T04:13:24.508ZMay 16 04:13:24.488 DEBG external link mgtriou_cr2_vn_vnic1@igb0 created
1962026-05-16T04:13:24.508ZMay 16 04:13:24.488 INFO creating nodes
1972026-05-16T04:13:24.508ZMay 16 04:13:24.488 INFO ox: launching node
1982026-05-16T04:13:24.508ZMay 16 04:13:24.492 INFO cr1: launching node
1992026-05-16T04:13:24.508ZMay 16 04:13:24.492 INFO cr2: launching node
2002026-05-16T04:13:24.533ZMay 16 04:13:24.506 INFO launched instance ox with pid 850 on port 41976
2012026-05-16T04:13:24.533ZMay 16 04:13:24.506 INFO ox: instance ensure
2022026-05-16T04:13:24.533ZMay 16 04:13:24.507 INFO launched instance cr1 with pid 851 on port 42016
2032026-05-16T04:13:24.533ZMay 16 04:13:24.507 INFO cr1: instance ensure
2042026-05-16T04:13:24.533ZMay 16 04:13:24.507 INFO launched instance cr2 with pid 852 on port 63279
2052026-05-16T04:13:24.533ZMay 16 04:13:24.507 INFO cr2: instance ensure
2062026-05-16T04:13:26.940ZMay 16 04:13:26.928 INFO cr2: instance ensure completed after 0 retries
2072026-05-16T04:13:26.940ZMay 16 04:13:26.928 INFO cr2: instance run
2082026-05-16T04:13:26.964ZMay 16 04:13:26.929 DEBG [sc] cr2: starting
2092026-05-16T04:13:26.965ZMay 16 04:13:26.929 DEBG [sc] cr2: connecting to [::1]:63279
2102026-05-16T04:13:26.965ZMay 16 04:13:26.930 DEBG [sc] cr2 waiting for prompt
2112026-05-16T04:13:26.995ZMay 16 04:13:26.984 INFO cr1: instance ensure completed after 0 retries
2122026-05-16T04:13:26.995ZMay 16 04:13:26.984 INFO cr1: instance run
2132026-05-16T04:13:27.020ZMay 16 04:13:26.984 DEBG [sc] cr1: starting
2142026-05-16T04:13:27.020ZMay 16 04:13:26.984 DEBG [sc] cr1: connecting to [::1]:42016
2152026-05-16T04:13:27.020ZMay 16 04:13:26.985 DEBG [sc] cr1 waiting for prompt
2162026-05-16T04:13:27.020ZMay 16 04:13:27.006 INFO ox: instance ensure completed after 0 retries
2172026-05-16T04:13:27.020ZMay 16 04:13:27.006 INFO ox: instance run
2182026-05-16T04:13:27.020ZMay 16 04:13:27.007 DEBG [sc] ox: starting
2192026-05-16T04:13:27.020ZMay 16 04:13:27.007 DEBG [sc] ox: connecting to [::1]:41976
2202026-05-16T04:13:27.020ZMay 16 04:13:27.007 DEBG [sc] ox waiting for prompt
2212026-05-16T04:13:44.040ZMay 16 04:13:44.028 DEBG [sc] cr1: logging in
2222026-05-16T04:13:44.409ZMay 16 04:13:44.397 INFO cr1: mounting /opt/cargo-bay
2232026-05-16T04:13:44.409ZMay 16 04:13:44.397 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2242026-05-16T04:13:44.434ZMay 16 04:13:44.420 DEBG [sc] cr1: executing command `cd`
2252026-05-16T04:13:44.458ZMay 16 04:13:44.431 INFO cr1: finished mounting /opt/cargo-bay
2262026-05-16T04:13:44.458ZMay 16 04:13:44.431 DEBG [sc] cr1: executing command `hostname cr1`
2272026-05-16T04:13:44.458ZMay 16 04:13:44.442 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
2282026-05-16T04:13:44.482ZMay 16 04:13:44.453 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
2292026-05-16T04:13:44.482ZMay 16 04:13:44.464 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
2302026-05-16T04:13:44.506ZMay 16 04:13:44.474 INFO cr1: logging out
2312026-05-16T04:13:46.552ZMay 16 04:13:46.540 INFO cr1: logged out
2322026-05-16T04:13:47.355ZMay 16 04:13:47.343 DEBG [sc] ox: logging in
2332026-05-16T04:13:47.537ZMay 16 04:13:47.525 INFO ox: mounting /opt/cargo-bay
2342026-05-16T04:13:47.537ZMay 16 04:13:47.525 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2352026-05-16T04:13:48.475ZMay 16 04:13:48.463 DEBG [sc] cr2: logging in
2362026-05-16T04:13:48.502ZMay 16 04:13:48.490 DEBG [sc] ox: executing command `cd`
2372026-05-16T04:13:48.526ZMay 16 04:13:48.500 INFO ox: finished mounting /opt/cargo-bay
2382026-05-16T04:13:48.526ZMay 16 04:13:48.500 DEBG [sc] ox: executing command `hostname ox`
2392026-05-16T04:13:48.526ZMay 16 04:13:48.512 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
2402026-05-16T04:13:48.551ZMay 16 04:13:48.523 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
2412026-05-16T04:13:48.551ZMay 16 04:13:48.534 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
2422026-05-16T04:13:48.575ZMay 16 04:13:48.545 INFO ox: logging out
2432026-05-16T04:13:48.645ZMay 16 04:13:48.633 INFO ox: logged out
2442026-05-16T04:13:48.874ZMay 16 04:13:48.862 INFO cr2: mounting /opt/cargo-bay
2452026-05-16T04:13:48.874ZMay 16 04:13:48.862 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2462026-05-16T04:13:48.899ZMay 16 04:13:48.884 DEBG [sc] cr2: executing command `cd`
2472026-05-16T04:13:48.923ZMay 16 04:13:48.895 INFO cr2: finished mounting /opt/cargo-bay
2482026-05-16T04:13:48.923ZMay 16 04:13:48.895 DEBG [sc] cr2: executing command `hostname cr2`
2492026-05-16T04:13:48.923ZMay 16 04:13:48.907 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
2502026-05-16T04:13:48.947ZMay 16 04:13:48.918 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
2512026-05-16T04:13:48.947ZMay 16 04:13:48.928 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
2522026-05-16T04:13:48.972ZMay 16 04:13:48.939 INFO cr2: logging out
2532026-05-16T04:13:51.917ZMay 16 04:13:51.905 INFO cr2: logged out
2542026-05-16T04:13:51.941ZMay 16 04:13:51.905 DEBG [sc] ox: starting
2552026-05-16T04:13:51.941ZMay 16 04:13:51.905 DEBG [sc] ox: connecting to [::1]:41976
2562026-05-16T04:13:51.941ZMay 16 04:13:51.906 DEBG [sc] ox waiting for prompt
2572026-05-16T04:13:51.941ZMay 16 04:13:51.917 DEBG [sc] ox: logging in
2582026-05-16T04:13:52.018ZMay 16 04:13:52.006 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
2592026-05-16T04:13:58.074ZMay 16 04:13:58.062 DEBG [sc] ox: starting
2602026-05-16T04:13:58.074ZMay 16 04:13:58.062 DEBG [sc] ox: connecting to [::1]:41976
2612026-05-16T04:13:58.099ZMay 16 04:13:58.063 DEBG [sc] ox waiting for prompt
2622026-05-16T04:13:58.099ZMay 16 04:13:58.073 DEBG [sc] ox: logging in
2632026-05-16T04:13:58.162ZMay 16 04:13:58.150 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
2642026-05-16T04:13:58.251ZMay 16 04:13:58.239 DEBG [sc] ox: starting
2652026-05-16T04:13:58.251ZMay 16 04:13:58.239 DEBG [sc] ox: connecting to [::1]:41976
2662026-05-16T04:13:58.275ZMay 16 04:13:58.240 DEBG [sc] ox waiting for prompt
2672026-05-16T04:13:58.275ZMay 16 04:13:58.250 DEBG [sc] ox: logging in
2682026-05-16T04:13:58.350ZMay 16 04:13:58.338 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
2692026-05-16T04:13:58.416ZMay 16 04:13:58.404 INFO cr1: installing frr
2702026-05-16T04:13:58.416ZMay 16 04:13:58.404 INFO waiting for ceos to initialize
2712026-05-16T04:13:58.416ZMay 16 04:13:58.404 INFO ox: setting up npuvm
2722026-05-16T04:13:58.440ZMay 16 04:13:58.405 DEBG [sc] cr2: starting
2732026-05-16T04:13:58.441ZMay 16 04:13:58.405 DEBG [sc] cr2: connecting to [::1]:63279
2742026-05-16T04:13:58.441ZMay 16 04:13:58.405 DEBG [sc] cr1: starting
2752026-05-16T04:13:58.441ZMay 16 04:13:58.405 DEBG [sc] cr1: connecting to [::1]:42016
2762026-05-16T04:13:58.441ZMay 16 04:13:58.405 DEBG [sc] ox: starting
2772026-05-16T04:13:58.441ZMay 16 04:13:58.405 DEBG [sc] ox: connecting to [::1]:41976
2782026-05-16T04:13:58.441ZMay 16 04:13:58.405 DEBG [sc] cr1 waiting for prompt
2792026-05-16T04:13:58.441ZMay 16 04:13:58.405 DEBG [sc] ox waiting for prompt
2802026-05-16T04:13:58.441ZMay 16 04:13:58.405 DEBG [sc] cr2 waiting for prompt
2812026-05-16T04:13:58.441ZMay 16 04:13:58.415 DEBG [sc] ox: logging in
2822026-05-16T04:13:58.441ZMay 16 04:13:58.416 DEBG [sc] cr2: logging in
2832026-05-16T04:13:58.441ZMay 16 04:13:58.416 DEBG [sc] cr1: logging in
2842026-05-16T04:13:58.515ZMay 16 04:13:58.504 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
2852026-05-16T04:13:58.571ZMay 16 04:13:58.560 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
2862026-05-16T04:13:58.765ZMay 16 04:13:58.754 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
2872026-05-16T04:14:00.873ZMay 16 04:14:00.861 INFO cr2: executing eos script show version
2882026-05-16T04:14:00.874ZMay 16 04:14:00.861 DEBG [sc] cr2: starting
2892026-05-16T04:14:00.874ZMay 16 04:14:00.861 DEBG [sc] cr2: connecting to [::1]:63279
2902026-05-16T04:14:00.913ZMay 16 04:14:00.862 DEBG [sc] cr2 waiting for prompt
2912026-05-16T04:14:00.913ZMay 16 04:14:00.872 DEBG [sc] cr2: logging in
2922026-05-16T04:14:01.028ZMay 16 04:14:01.016 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
2932026-05-16T04:14:03.812ZMay 16 04:14:03.801 DEBG [sc] ox: starting
2942026-05-16T04:14:03.813ZMay 16 04:14:03.801 DEBG [sc] ox: connecting to [::1]:41976
2952026-05-16T04:14:03.837ZMay 16 04:14:03.801 DEBG [sc] ox waiting for prompt
2962026-05-16T04:14:03.837ZMay 16 04:14:03.811 DEBG [sc] ox: logging in
2972026-05-16T04:14:03.900ZMay 16 04:14:03.888 DEBG [sc] ox: executing command `chmod +x npuvm`
2982026-05-16T04:14:03.967ZMay 16 04:14:03.955 DEBG [sc] ox: starting
2992026-05-16T04:14:03.967ZMay 16 04:14:03.955 DEBG [sc] ox: connecting to [::1]:41976
3002026-05-16T04:14:03.991ZMay 16 04:14:03.956 DEBG [sc] ox waiting for prompt
3012026-05-16T04:14:03.991ZMay 16 04:14:03.966 DEBG [sc] ox: logging in
3022026-05-16T04:14:04.054ZMay 16 04:14:04.043 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
3032026-05-16T04:14:09.353ZMay 16 04:14:09.341 DEBG [sc] cr2: starting
3042026-05-16T04:14:09.353ZMay 16 04:14:09.341 DEBG [sc] cr2: connecting to [::1]:63279
3052026-05-16T04:14:09.377ZMay 16 04:14:09.342 DEBG [sc] cr2 waiting for prompt
3062026-05-16T04:14:09.377ZMay 16 04:14:09.352 DEBG [sc] cr2: logging in
3072026-05-16T04:14:09.507ZMay 16 04:14:09.495 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3082026-05-16T04:14:11.651ZMay 16 04:14:11.640 INFO cr2: executing eos script show version
3092026-05-16T04:14:11.651ZMay 16 04:14:11.640 DEBG [sc] cr2: starting
3102026-05-16T04:14:11.651ZMay 16 04:14:11.640 DEBG [sc] cr2: connecting to [::1]:63279
3112026-05-16T04:14:11.676ZMay 16 04:14:11.640 DEBG [sc] cr2 waiting for prompt
3122026-05-16T04:14:11.676ZMay 16 04:14:11.650 DEBG [sc] cr2: logging in
3132026-05-16T04:14:11.805ZMay 16 04:14:11.794 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3142026-05-16T04:14:14.202ZMay 16 04:14:14.190 INFO cr2: executing eos script
3152026-05-16T04:14:14.202Z enable
3162026-05-16T04:14:14.202Z configure
3172026-05-16T04:14:14.202Z ipv6 unicast-routing
3182026-05-16T04:14:14.202Z ip routing ipv6 interfaces
3192026-05-16T04:14:14.202Z ip routing
3202026-05-16T04:14:14.203Z ip route 1.2.3.0/24 null0
3212026-05-16T04:14:14.203Z ipv6 route fd99::/64 null0
3222026-05-16T04:14:14.203Z interface et1
3232026-05-16T04:14:14.203Z no switchport
3242026-05-16T04:14:14.203Z ipv6 enable
3252026-05-16T04:14:14.203Z
3262026-05-16T04:14:14.203Z router bgp 45
3272026-05-16T04:14:14.203Z router-id 1.2.3.1
3282026-05-16T04:14:14.203Z no bgp default ipv4-unicast
3292026-05-16T04:14:14.203Z timers bgp 2 6
3302026-05-16T04:14:14.203Z neighbor ebgp peer group
3312026-05-16T04:14:14.203Z neighbor ebgp remote-as 33
3322026-05-16T04:14:14.203Z neighbor interface Et1 peer-group ebgp
3332026-05-16T04:14:14.203Z address-family ipv4
3342026-05-16T04:14:14.203Z neighbor ebgp activate
3352026-05-16T04:14:14.203Z neighbor ebgp next-hop address-family ipv6 originate
3362026-05-16T04:14:14.203Z network 1.2.3.0/24
3372026-05-16T04:14:14.203Z exit
3382026-05-16T04:14:14.203Z address-family ipv6
3392026-05-16T04:14:14.203Z neighbor ebgp activate
3402026-05-16T04:14:14.203Z neighbor ebgp next-hop address-family ipv6 originate
3412026-05-16T04:14:14.203Z network fd99::/64
3422026-05-16T04:14:14.203Z exit
3432026-05-16T04:14:14.203Z exit
3442026-05-16T04:14:14.203Z
3452026-05-16T04:14:14.203ZMay 16 04:14:14.190 DEBG [sc] cr2: starting
3462026-05-16T04:14:14.203ZMay 16 04:14:14.190 DEBG [sc] cr2: connecting to [::1]:63279
3472026-05-16T04:14:14.228ZMay 16 04:14:14.191 DEBG [sc] cr2 waiting for prompt
3482026-05-16T04:14:14.228ZMay 16 04:14:14.201 DEBG [sc] cr2: logging in
3492026-05-16T04:14:14.378ZMay 16 04:14:14.366 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
3502026-05-16T04:14:14.378Z enable
3512026-05-16T04:14:14.378Z configure
3522026-05-16T04:14:14.378Z ipv6 unicast-routing
3532026-05-16T04:14:14.378Z ip routing ipv6 interfaces
3542026-05-16T04:14:14.378Z ip routing
3552026-05-16T04:14:14.378Z ip route 1.2.3.0/24 null0
3562026-05-16T04:14:14.379Z ipv6 route fd99::/64 null0
3572026-05-16T04:14:14.379Z interface et1
3582026-05-16T04:14:14.379Z no switchport
3592026-05-16T04:14:14.379Z ipv6 enable
3602026-05-16T04:14:14.379Z
3612026-05-16T04:14:14.379Z router bgp 45
3622026-05-16T04:14:14.379Z router-id 1.2.3.1
3632026-05-16T04:14:14.379Z no bgp default ipv4-unicast
3642026-05-16T04:14:14.379Z timers bgp 2 6
3652026-05-16T04:14:14.379Z neighbor ebgp peer group
3662026-05-16T04:14:14.379Z neighbor ebgp remote-as 33
3672026-05-16T04:14:14.379Z neighbor interface Et1 peer-group ebgp
3682026-05-16T04:14:14.379Z address-family ipv4
3692026-05-16T04:14:14.379Z neighbor ebgp activate
3702026-05-16T04:14:14.379Z neighbor ebgp next-hop address-family ipv6 originate
3712026-05-16T04:14:14.379Z network 1.2.3.0/24
3722026-05-16T04:14:14.379Z exit
3732026-05-16T04:14:14.379Z address-family ipv6
3742026-05-16T04:14:14.379Z neighbor ebgp activate
3752026-05-16T04:14:14.379Z neighbor ebgp next-hop address-family ipv6 originate
3762026-05-16T04:14:14.379Z network fd99::/64
3772026-05-16T04:14:14.379Z exit
3782026-05-16T04:14:14.379Z exit
3792026-05-16T04:14:14.379Z '`
3802026-05-16T04:14:36.412ZMay 16 04:14:36.400 INFO cr1: enabling frr daemon bgpd
3812026-05-16T04:14:36.412ZMay 16 04:14:36.400 DEBG [sc] cr1: starting
3822026-05-16T04:14:36.412ZMay 16 04:14:36.400 DEBG [sc] cr1: connecting to [::1]:42016
3832026-05-16T04:14:36.436ZMay 16 04:14:36.400 DEBG [sc] cr1 waiting for prompt
3842026-05-16T04:14:36.436ZMay 16 04:14:36.411 DEBG [sc] cr1: logging in
3852026-05-16T04:14:36.568ZMay 16 04:14:36.556 DEBG [sc] cr1: executing command `sed -i 's/bgpd=no/bgpd=yes/g' /etc/frr/daemons`
3862026-05-16T04:14:38.663ZMay 16 04:14:38.652 DEBG [sc] cr1: starting
3872026-05-16T04:14:38.663ZMay 16 04:14:38.652 DEBG [sc] cr1: connecting to [::1]:42016
3882026-05-16T04:14:38.688ZMay 16 04:14:38.652 DEBG [sc] cr1 waiting for prompt
3892026-05-16T04:14:38.688ZMay 16 04:14:38.662 DEBG [sc] cr1: logging in
3902026-05-16T04:14:38.807ZMay 16 04:14:38.795 DEBG [sc] cr1: executing command `systemctl restart frr`
3912026-05-16T04:14:46.464ZMay 16 04:14:46.451 INFO cr1: executing frr script
3922026-05-16T04:14:46.464Z configure
3932026-05-16T04:14:46.464Z ip forwarding
3942026-05-16T04:14:46.464Z ipv6 forwarding
3952026-05-16T04:14:46.464Z ip route 1.2.3.0/24 null0
3962026-05-16T04:14:46.464Z ipv6 route fd99::/64 null0
3972026-05-16T04:14:46.464Z router bgp 44
3982026-05-16T04:14:46.464Z no bgp ebgp-requires-policy
3992026-05-16T04:14:46.464Z timers bgp 2 6
4002026-05-16T04:14:46.464Z neighbor enp0s8 interface remote-as external
4012026-05-16T04:14:46.464Z neighbor enp0s8 timers connect 1
4022026-05-16T04:14:46.464Z address-family ipv4 unicast
4032026-05-16T04:14:46.464Z network 1.2.3.0/24
4042026-05-16T04:14:46.464Z neighbor enp0s8 activate
4052026-05-16T04:14:46.464Z exit-address-family
4062026-05-16T04:14:46.464Z address-family ipv6 unicast
4072026-05-16T04:14:46.464Z network fd99::/64
4082026-05-16T04:14:46.464Z neighbor enp0s8 activate
4092026-05-16T04:14:46.464Z exit-address-family
4102026-05-16T04:14:46.464Z exit
4112026-05-16T04:14:46.464Z
4122026-05-16T04:14:46.464ZMay 16 04:14:46.452 DEBG [sc] cr1: starting
4132026-05-16T04:14:46.464ZMay 16 04:14:46.452 DEBG [sc] cr1: connecting to [::1]:42016
4142026-05-16T04:14:46.489ZMay 16 04:14:46.452 DEBG [sc] cr1 waiting for prompt
4152026-05-16T04:14:46.489ZMay 16 04:14:46.464 DEBG [sc] cr1: logging in
4162026-05-16T04:14:46.629ZMay 16 04:14:46.618 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 ' '`
4172026-05-16T04:15:52.260ZMay 16 04:15:52.248 DEBG [sc] ox: starting
4182026-05-16T04:15:52.260ZMay 16 04:15:52.248 DEBG [sc] ox: connecting to [::1]:41976
4192026-05-16T04:15:52.284ZMay 16 04:15:52.248 DEBG [sc] ox waiting for prompt
4202026-05-16T04:15:52.284ZMay 16 04:15:52.259 DEBG [sc] ox: logging in
4212026-05-16T04:15:52.351ZMay 16 04:15:52.338 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
4222026-05-16T04:15:52.598ZMay 16 04:15:52.586 DEBG [sc] ox: starting
4232026-05-16T04:15:52.598ZMay 16 04:15:52.586 DEBG [sc] ox: connecting to [::1]:41976
4242026-05-16T04:15:52.623ZMay 16 04:15:52.587 DEBG [sc] ox waiting for prompt
4252026-05-16T04:15:52.623ZMay 16 04:15:52.598 DEBG [sc] ox: logging in
4262026-05-16T04:15:52.687ZMay 16 04:15:52.675 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4272026-05-16T04:15:53.710ZMay 16 04:15:53.699 DEBG [sc] ox: starting
4282026-05-16T04:15:53.710ZMay 16 04:15:53.699 DEBG [sc] ox: connecting to [::1]:41976
4292026-05-16T04:15:53.735ZMay 16 04:15:53.700 DEBG [sc] ox waiting for prompt
4302026-05-16T04:15:53.735ZMay 16 04:15:53.700 DEBG [sc] ox: logging in
4312026-05-16T04:15:53.789ZMay 16 04:15:53.777 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4322026-05-16T04:15:53.845ZMay 16 04:15:53.833 DEBG [sc] ox: starting
4332026-05-16T04:15:53.845ZMay 16 04:15:53.833 DEBG [sc] ox: connecting to [::1]:41976
4342026-05-16T04:15:53.870ZMay 16 04:15:53.834 DEBG [sc] ox waiting for prompt
4352026-05-16T04:15:53.870ZMay 16 04:15:53.844 DEBG [sc] ox: logging in
4362026-05-16T04:15:53.935ZMay 16 04:15:53.923 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
4372026-05-16T04:15:53.990ZMay 16 04:15:53.978 DEBG [sc] ox: starting
4382026-05-16T04:15:53.991ZMay 16 04:15:53.978 DEBG [sc] ox: connecting to [::1]:41976
4392026-05-16T04:15:54.015ZMay 16 04:15:53.979 DEBG [sc] ox waiting for prompt
4402026-05-16T04:15:54.015ZMay 16 04:15:53.988 DEBG [sc] ox: logging in
4412026-05-16T04:15:54.079ZMay 16 04:15:54.067 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
4422026-05-16T04:15:54.134ZMay 16 04:15:54.122 DEBG [sc] ox: starting
4432026-05-16T04:15:54.134ZMay 16 04:15:54.122 DEBG [sc] ox: connecting to [::1]:41976
4442026-05-16T04:15:54.158ZMay 16 04:15:54.123 DEBG [sc] ox waiting for prompt
4452026-05-16T04:15:54.158ZMay 16 04:15:54.133 DEBG [sc] ox: logging in
4462026-05-16T04:15:54.222ZMay 16 04:15:54.210 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
4472026-05-16T04:15:54.277ZMay 16 04:15:54.265 DEBG [sc] ox: starting
4482026-05-16T04:15:54.277ZMay 16 04:15:54.265 DEBG [sc] ox: connecting to [::1]:41976
4492026-05-16T04:15:54.301ZMay 16 04:15:54.266 DEBG [sc] ox waiting for prompt
4502026-05-16T04:15:54.301ZMay 16 04:15:54.276 DEBG [sc] ox: logging in
4512026-05-16T04:15:54.365ZMay 16 04:15:54.353 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
4522026-05-16T04:15:54.421ZMay 16 04:15:54.409 DEBG [sc] ox: starting
4532026-05-16T04:15:54.421ZMay 16 04:15:54.409 DEBG [sc] ox: connecting to [::1]:41976
4542026-05-16T04:15:54.445ZMay 16 04:15:54.409 DEBG [sc] ox waiting for prompt
4552026-05-16T04:15:54.445ZMay 16 04:15:54.420 DEBG [sc] ox: logging in
4562026-05-16T04:15:54.510ZMay 16 04:15:54.498 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
4572026-05-16T04:15:54.576ZMay 16 04:15:54.564 DEBG [sc] ox: starting
4582026-05-16T04:15:54.576ZMay 16 04:15:54.564 DEBG [sc] ox: connecting to [::1]:41976
4592026-05-16T04:15:54.600ZMay 16 04:15:54.565 DEBG [sc] ox waiting for prompt
4602026-05-16T04:15:54.600ZMay 16 04:15:54.575 DEBG [sc] ox: logging in
4612026-05-16T04:15:54.675ZMay 16 04:15:54.664 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
4622026-05-16T04:15:54.741ZMay 16 04:15:54.729 DEBG [sc] ox: starting
4632026-05-16T04:15:54.741ZMay 16 04:15:54.729 DEBG [sc] ox: connecting to [::1]:41976
4642026-05-16T04:15:54.766ZMay 16 04:15:54.730 DEBG [sc] ox waiting for prompt
4652026-05-16T04:15:54.766ZMay 16 04:15:54.741 DEBG [sc] ox: logging in
4662026-05-16T04:15:54.840ZMay 16 04:15:54.829 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
4672026-05-16T04:15:54.912ZMay 16 04:15:54.900 INFO adding BGP router to mgd
4682026-05-16T04:15:57.378ZMay 16 04:15:57.366 INFO cr1: executing frr script show ip bgp json
4692026-05-16T04:15:57.378ZMay 16 04:15:57.366 DEBG [sc] cr1: starting
4702026-05-16T04:15:57.378ZMay 16 04:15:57.366 DEBG [sc] cr1: connecting to [::1]:42016
4712026-05-16T04:15:57.402ZMay 16 04:15:57.367 DEBG [sc] cr1 waiting for prompt
4722026-05-16T04:15:57.402ZMay 16 04:15:57.377 DEBG [sc] cr1: logging in
4732026-05-16T04:15:57.706ZMay 16 04:15:57.694 DEBG [sc] cr1: executing command `vtysh -c 'show ip bgp json'`
4742026-05-16T04:15:59.827ZMay 16 04:15:59.815 INFO cr1: executing frr script show bgp json
4752026-05-16T04:15:59.851ZMay 16 04:15:59.815 DEBG [sc] cr1: starting
4762026-05-16T04:15:59.851ZMay 16 04:15:59.815 DEBG [sc] cr1: connecting to [::1]:42016
4772026-05-16T04:15:59.851ZMay 16 04:15:59.816 DEBG [sc] cr1 waiting for prompt
4782026-05-16T04:15:59.851ZMay 16 04:15:59.826 DEBG [sc] cr1: logging in
4792026-05-16T04:15:59.970ZMay 16 04:15:59.958 DEBG [sc] cr1: executing command `vtysh -c 'show bgp json'`
4802026-05-16T04:16:02.090ZMay 16 04:16:02.078 INFO cr2: executing eos script show ip bgp | json
4812026-05-16T04:16:02.115ZMay 16 04:16:02.078 DEBG [sc] cr2: starting
4822026-05-16T04:16:02.115ZMay 16 04:16:02.078 DEBG [sc] cr2: connecting to [::1]:63279
4832026-05-16T04:16:02.115ZMay 16 04:16:02.079 DEBG [sc] cr2 waiting for prompt
4842026-05-16T04:16:02.115ZMay 16 04:16:02.089 DEBG [sc] cr2: logging in
4852026-05-16T04:16:02.420ZMay 16 04:16:02.408 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ip bgp | json'`
4862026-05-16T04:16:04.829ZMay 16 04:16:04.817 INFO cr2: executing eos script show ipv6 bgp | json
4872026-05-16T04:16:04.829ZMay 16 04:16:04.817 DEBG [sc] cr2: starting
4882026-05-16T04:16:04.829ZMay 16 04:16:04.817 DEBG [sc] cr2: connecting to [::1]:63279
4892026-05-16T04:16:04.853ZMay 16 04:16:04.818 DEBG [sc] cr2 waiting for prompt
4902026-05-16T04:16:04.853ZMay 16 04:16:04.828 DEBG [sc] cr2: logging in
4912026-05-16T04:16:04.983ZMay 16 04:16:04.971 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ipv6 bgp | json'`
4922026-05-16T04:16:07.370ZMay 16 04:16:07.357 INFO trio bgp unnumbered test passed 🎉
4932026-05-16T04:16:07.370ZMay 16 04:16:07.357 INFO destroying runner for deployment mgtriou
4942026-05-16T04:16:07.370ZMay 16 04:16:07.357 INFO destroying deployment mgtriou
4952026-05-16T04:16:07.370ZMay 16 04:16:07.357 INFO destroying nodes
4962026-05-16T04:16:07.490ZMay 16 04:16:07.478 INFO destroying links
4972026-05-16T04:16:07.490ZMay 16 04:16:07.478 INFO destroying link mgtriou_ox_sn_vnic0
4982026-05-16T04:16:07.514ZMay 16 04:16:07.481 INFO destroying link mgtriou_ox_sn_sim0
4992026-05-16T04:16:07.514ZMay 16 04:16:07.482 INFO destroying link mgtriou_cr1_vn_vnic0
5002026-05-16T04:16:08.497ZMay 16 04:16:08.485 INFO destroying link mgtriou_cr1_vn_sim0
5012026-05-16T04:16:08.521ZMay 16 04:16:08.486 INFO destroying link mgtriou_ox_sn_vnic1
5022026-05-16T04:16:08.521ZMay 16 04:16:08.487 INFO destroying link mgtriou_ox_sn_sim1
5032026-05-16T04:16:08.522ZMay 16 04:16:08.488 INFO destroying link mgtriou_cr2_vn_vnic0
5042026-05-16T04:16:08.522ZMay 16 04:16:08.490 INFO destroying link mgtriou_cr2_vn_sim0
5052026-05-16T04:16:08.522ZMay 16 04:16:08.491 INFO destroying external links
5062026-05-16T04:16:08.522ZMay 16 04:16:08.491 INFO destroying external link mgtriou_ox_vn_vnic2
5072026-05-16T04:16:08.522ZMay 16 04:16:08.492 INFO destroying external link mgtriou_cr1_vn_vnic1
5082026-05-16T04:16:08.522ZMay 16 04:16:08.493 INFO destroying external link mgtriou_cr2_vn_vnic1
5092026-05-16T04:16:08.522ZMay 16 04:16:08.495 INFO destroying images
5102026-05-16T04:16:08.981ZMay 16 04:16:08.969 INFO destroying workspace at .falcon
5112026-05-16T04:16:09.005Z+ RUST_LOG=debug
5122026-05-16T04:16:09.005Z+ pfexec ./falcon-lab run trio-bfd-static-routing
5132026-05-16T04:16:09.030ZMay 16 04:16:09.009 DEBG using default route interface igb0
5142026-05-16T04:16:09.030ZMay 16 04:16:09.009 DEBG using default route interface igb0
5152026-05-16T04:16:09.030ZMay 16 04:16:09.009 DEBG using default route interface igb0
5162026-05-16T04:16:09.030ZMay 16 04:16:09.009 INFO launching runner: deployment(mgtriobfd) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
5172026-05-16T04:16:09.030ZMay 16 04:16:09.009 INFO starting preflight for deployment mgtriobfd
5182026-05-16T04:16:09.777ZMay 16 04:16:09.765 INFO creating links
5192026-05-16T04:16:09.777ZMay 16 04:16:09.765 DEBG destroying link mgtriobfd_ox_sn_vnic0
5202026-05-16T04:16:09.777ZMay 16 04:16:09.765 DEBG destroying link mgtriobfd_ox_sn_sim0
5212026-05-16T04:16:09.777ZMay 16 04:16:09.765 INFO creating simnet link 'mgtriobfd_ox_sn_sim0'
5222026-05-16T04:16:09.801ZMay 16 04:16:09.768 INFO creating vnic link 'mgtriobfd_ox_sn_vnic0'
5232026-05-16T04:16:09.801ZMay 16 04:16:09.774 DEBG link pair created
5242026-05-16T04:16:09.801ZMay 16 04:16:09.775 DEBG destroying link mgtriobfd_cr1_vn_vnic0
5252026-05-16T04:16:09.801ZMay 16 04:16:09.775 DEBG destroying link mgtriobfd_cr1_vn_sim0
5262026-05-16T04:16:09.801ZMay 16 04:16:09.775 INFO creating simnet link 'mgtriobfd_cr1_vn_sim0'
5272026-05-16T04:16:09.801ZMay 16 04:16:09.776 INFO creating vnic link 'mgtriobfd_cr1_vn_vnic0'
5282026-05-16T04:16:09.801ZMay 16 04:16:09.783 DEBG link pair created
5292026-05-16T04:16:09.801ZMay 16 04:16:09.783 DEBG destroying link mgtriobfd_ox_sn_vnic1
5302026-05-16T04:16:09.801ZMay 16 04:16:09.783 DEBG destroying link mgtriobfd_ox_sn_sim1
5312026-05-16T04:16:09.801ZMay 16 04:16:09.783 INFO creating simnet link 'mgtriobfd_ox_sn_sim1'
5322026-05-16T04:16:09.801ZMay 16 04:16:09.784 INFO creating vnic link 'mgtriobfd_ox_sn_vnic1'
5332026-05-16T04:16:09.826ZMay 16 04:16:09.789 DEBG link pair created
5342026-05-16T04:16:09.826ZMay 16 04:16:09.789 DEBG destroying link mgtriobfd_cr2_vn_vnic0
5352026-05-16T04:16:09.826ZMay 16 04:16:09.789 DEBG destroying link mgtriobfd_cr2_vn_sim0
5362026-05-16T04:16:09.826ZMay 16 04:16:09.789 INFO creating simnet link 'mgtriobfd_cr2_vn_sim0'
5372026-05-16T04:16:09.826ZMay 16 04:16:09.791 INFO creating vnic link 'mgtriobfd_cr2_vn_vnic0'
5382026-05-16T04:16:09.826ZMay 16 04:16:09.798 DEBG link pair created
5392026-05-16T04:16:09.826ZMay 16 04:16:09.798 INFO creating external links
5402026-05-16T04:16:09.826ZMay 16 04:16:09.798 DEBG destroying external link mgtriobfd_ox_vn_vnic2
5412026-05-16T04:16:09.826ZMay 16 04:16:09.798 INFO creating external link mgtriobfd_ox_vn_vnic2
5422026-05-16T04:16:09.826ZMay 16 04:16:09.799 DEBG external link mgtriobfd_ox_vn_vnic2@igb0 created
5432026-05-16T04:16:09.826ZMay 16 04:16:09.799 DEBG destroying external link mgtriobfd_cr1_vn_vnic1
5442026-05-16T04:16:09.826ZMay 16 04:16:09.799 INFO creating external link mgtriobfd_cr1_vn_vnic1
5452026-05-16T04:16:09.826ZMay 16 04:16:09.800 DEBG external link mgtriobfd_cr1_vn_vnic1@igb0 created
5462026-05-16T04:16:09.826ZMay 16 04:16:09.800 DEBG destroying external link mgtriobfd_cr2_vn_vnic1
5472026-05-16T04:16:09.826ZMay 16 04:16:09.800 INFO creating external link mgtriobfd_cr2_vn_vnic1
5482026-05-16T04:16:09.826ZMay 16 04:16:09.801 DEBG external link mgtriobfd_cr2_vn_vnic1@igb0 created
5492026-05-16T04:16:09.826ZMay 16 04:16:09.801 INFO creating nodes
5502026-05-16T04:16:09.826ZMay 16 04:16:09.801 INFO ox: launching node
5512026-05-16T04:16:09.827ZMay 16 04:16:09.804 INFO cr1: launching node
5522026-05-16T04:16:09.827ZMay 16 04:16:09.806 INFO cr2: launching node
5532026-05-16T04:16:09.851ZMay 16 04:16:09.820 INFO launched instance ox with pid 889 on port 53488
5542026-05-16T04:16:09.851ZMay 16 04:16:09.820 INFO ox: instance ensure
5552026-05-16T04:16:09.851ZMay 16 04:16:09.820 INFO launched instance cr1 with pid 890 on port 56852
5562026-05-16T04:16:09.851ZMay 16 04:16:09.821 INFO cr1: instance ensure
5572026-05-16T04:16:09.851ZMay 16 04:16:09.821 INFO launched instance cr2 with pid 891 on port 56614
5582026-05-16T04:16:09.851ZMay 16 04:16:09.821 INFO cr2: instance ensure
5592026-05-16T04:16:11.860ZMay 16 04:16:11.848 INFO cr1: instance ensure completed after 0 retries
5602026-05-16T04:16:11.860ZMay 16 04:16:11.848 INFO cr1: instance run
5612026-05-16T04:16:11.884ZMay 16 04:16:11.848 DEBG [sc] cr1: starting
5622026-05-16T04:16:11.884ZMay 16 04:16:11.848 DEBG [sc] cr1: connecting to [::1]:56852
5632026-05-16T04:16:11.884ZMay 16 04:16:11.849 DEBG [sc] cr1 waiting for prompt
5642026-05-16T04:16:11.956ZMay 16 04:16:11.944 INFO cr2: instance ensure completed after 0 retries
5652026-05-16T04:16:11.956ZMay 16 04:16:11.944 INFO cr2: instance run
5662026-05-16T04:16:11.980ZMay 16 04:16:11.944 DEBG [sc] cr2: starting
5672026-05-16T04:16:11.980ZMay 16 04:16:11.944 DEBG [sc] cr2: connecting to [::1]:56614
5682026-05-16T04:16:11.980ZMay 16 04:16:11.945 DEBG [sc] cr2 waiting for prompt
5692026-05-16T04:16:12.004ZMay 16 04:16:11.983 INFO ox: instance ensure completed after 0 retries
5702026-05-16T04:16:12.004ZMay 16 04:16:11.983 INFO ox: instance run
5712026-05-16T04:16:12.004ZMay 16 04:16:11.984 DEBG [sc] ox: starting
5722026-05-16T04:16:12.004ZMay 16 04:16:11.984 DEBG [sc] ox: connecting to [::1]:53488
5732026-05-16T04:16:12.004ZMay 16 04:16:11.984 DEBG [sc] ox waiting for prompt
5742026-05-16T04:16:29.052ZMay 16 04:16:29.039 DEBG [sc] cr1: logging in
5752026-05-16T04:16:29.464ZMay 16 04:16:29.451 INFO cr1: mounting /opt/cargo-bay
5762026-05-16T04:16:29.464ZMay 16 04:16:29.451 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5772026-05-16T04:16:29.489ZMay 16 04:16:29.474 DEBG [sc] cr1: executing command `cd`
5782026-05-16T04:16:29.514ZMay 16 04:16:29.485 INFO cr1: finished mounting /opt/cargo-bay
5792026-05-16T04:16:29.514ZMay 16 04:16:29.485 DEBG [sc] cr1: executing command `hostname cr1`
5802026-05-16T04:16:29.514ZMay 16 04:16:29.496 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
5812026-05-16T04:16:29.539ZMay 16 04:16:29.507 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
5822026-05-16T04:16:29.539ZMay 16 04:16:29.518 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
5832026-05-16T04:16:29.564ZMay 16 04:16:29.530 INFO cr1: logging out
5842026-05-16T04:16:31.607ZMay 16 04:16:31.596 INFO cr1: logged out
5852026-05-16T04:16:32.883ZMay 16 04:16:32.871 DEBG [sc] ox: logging in
5862026-05-16T04:16:33.069ZMay 16 04:16:33.057 INFO ox: mounting /opt/cargo-bay
5872026-05-16T04:16:33.069ZMay 16 04:16:33.057 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5882026-05-16T04:16:33.653ZMay 16 04:16:33.641 DEBG [sc] cr2: logging in
5892026-05-16T04:16:34.072ZMay 16 04:16:34.060 INFO cr2: mounting /opt/cargo-bay
5902026-05-16T04:16:34.072ZMay 16 04:16:34.060 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5912026-05-16T04:16:34.097ZMay 16 04:16:34.069 DEBG [sc] ox: executing command `cd`
5922026-05-16T04:16:34.097ZMay 16 04:16:34.071 DEBG [sc] cr2: executing command `cd`
5932026-05-16T04:16:34.097ZMay 16 04:16:34.080 INFO ox: finished mounting /opt/cargo-bay
5942026-05-16T04:16:34.097ZMay 16 04:16:34.080 DEBG [sc] ox: executing command `hostname ox`
5952026-05-16T04:16:34.097ZMay 16 04:16:34.081 INFO cr2: finished mounting /opt/cargo-bay
5962026-05-16T04:16:34.097ZMay 16 04:16:34.081 DEBG [sc] cr2: executing command `hostname cr2`
5972026-05-16T04:16:34.121ZMay 16 04:16:34.091 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
5982026-05-16T04:16:34.121ZMay 16 04:16:34.092 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
5992026-05-16T04:16:34.121ZMay 16 04:16:34.101 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
6002026-05-16T04:16:34.121ZMay 16 04:16:34.103 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
6012026-05-16T04:16:34.145ZMay 16 04:16:34.112 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
6022026-05-16T04:16:34.145ZMay 16 04:16:34.114 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
6032026-05-16T04:16:34.145ZMay 16 04:16:34.123 INFO ox: logging out
6042026-05-16T04:16:34.145ZMay 16 04:16:34.125 INFO cr2: logging out
6052026-05-16T04:16:34.223ZMay 16 04:16:34.212 INFO ox: logged out
6062026-05-16T04:16:37.137ZMay 16 04:16:37.125 INFO cr2: logged out
6072026-05-16T04:16:37.161ZMay 16 04:16:37.125 DEBG [sc] ox: starting
6082026-05-16T04:16:37.161ZMay 16 04:16:37.125 DEBG [sc] ox: connecting to [::1]:53488
6092026-05-16T04:16:37.161ZMay 16 04:16:37.126 DEBG [sc] ox waiting for prompt
6102026-05-16T04:16:37.162ZMay 16 04:16:37.137 DEBG [sc] ox: logging in
6112026-05-16T04:16:37.237ZMay 16 04:16:37.225 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
6122026-05-16T04:16:43.398ZMay 16 04:16:43.386 DEBG [sc] ox: starting
6132026-05-16T04:16:43.398ZMay 16 04:16:43.386 DEBG [sc] ox: connecting to [::1]:53488
6142026-05-16T04:16:43.422ZMay 16 04:16:43.386 DEBG [sc] ox waiting for prompt
6152026-05-16T04:16:43.422ZMay 16 04:16:43.396 DEBG [sc] ox: logging in
6162026-05-16T04:16:43.485ZMay 16 04:16:43.473 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
6172026-05-16T04:16:43.562ZMay 16 04:16:43.550 DEBG [sc] ox: starting
6182026-05-16T04:16:43.562ZMay 16 04:16:43.550 DEBG [sc] ox: connecting to [::1]:53488
6192026-05-16T04:16:43.586ZMay 16 04:16:43.551 DEBG [sc] ox waiting for prompt
6202026-05-16T04:16:43.586ZMay 16 04:16:43.561 DEBG [sc] ox: logging in
6212026-05-16T04:16:43.661ZMay 16 04:16:43.649 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
6222026-05-16T04:16:43.728ZMay 16 04:16:43.716 INFO cr1: installing frr
6232026-05-16T04:16:43.728ZMay 16 04:16:43.716 INFO waiting for ceos to initialize
6242026-05-16T04:16:43.728ZMay 16 04:16:43.716 INFO ox: setting up npuvm
6252026-05-16T04:16:43.752ZMay 16 04:16:43.716 DEBG [sc] cr2: starting
6262026-05-16T04:16:43.752ZMay 16 04:16:43.716 DEBG [sc] cr2: connecting to [::1]:56614
6272026-05-16T04:16:43.752ZMay 16 04:16:43.716 DEBG [sc] cr1: starting
6282026-05-16T04:16:43.752ZMay 16 04:16:43.716 DEBG [sc] cr1: connecting to [::1]:56852
6292026-05-16T04:16:43.752ZMay 16 04:16:43.716 DEBG [sc] ox: starting
6302026-05-16T04:16:43.752ZMay 16 04:16:43.716 DEBG [sc] ox: connecting to [::1]:53488
6312026-05-16T04:16:43.752ZMay 16 04:16:43.717 DEBG [sc] cr2 waiting for prompt
6322026-05-16T04:16:43.752ZMay 16 04:16:43.717 DEBG [sc] cr1 waiting for prompt
6332026-05-16T04:16:43.752ZMay 16 04:16:43.717 DEBG [sc] ox waiting for prompt
6342026-05-16T04:16:43.752ZMay 16 04:16:43.727 DEBG [sc] ox: logging in
6352026-05-16T04:16:43.752ZMay 16 04:16:43.728 DEBG [sc] cr1: logging in
6362026-05-16T04:16:43.752ZMay 16 04:16:43.728 DEBG [sc] cr2: logging in
6372026-05-16T04:16:43.827ZMay 16 04:16:43.815 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
6382026-05-16T04:16:43.884ZMay 16 04:16:43.872 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6392026-05-16T04:16:44.070ZMay 16 04:16:44.058 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
6402026-05-16T04:16:46.132ZMay 16 04:16:46.119 INFO cr2: executing eos script show version
6412026-05-16T04:16:46.132ZMay 16 04:16:46.119 DEBG [sc] cr2: starting
6422026-05-16T04:16:46.132ZMay 16 04:16:46.119 DEBG [sc] cr2: connecting to [::1]:56614
6432026-05-16T04:16:46.157ZMay 16 04:16:46.120 DEBG [sc] cr2 waiting for prompt
6442026-05-16T04:16:46.157ZMay 16 04:16:46.130 DEBG [sc] cr2: logging in
6452026-05-16T04:16:46.285ZMay 16 04:16:46.273 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6462026-05-16T04:16:50.156ZMay 16 04:16:50.144 DEBG [sc] ox: starting
6472026-05-16T04:16:50.157ZMay 16 04:16:50.144 DEBG [sc] ox: connecting to [::1]:53488
6482026-05-16T04:16:50.181ZMay 16 04:16:50.145 DEBG [sc] ox waiting for prompt
6492026-05-16T04:16:50.181ZMay 16 04:16:50.155 DEBG [sc] ox: logging in
6502026-05-16T04:16:50.244ZMay 16 04:16:50.232 DEBG [sc] ox: executing command `chmod +x npuvm`
6512026-05-16T04:16:50.312ZMay 16 04:16:50.299 DEBG [sc] ox: starting
6522026-05-16T04:16:50.312ZMay 16 04:16:50.299 DEBG [sc] ox: connecting to [::1]:53488
6532026-05-16T04:16:50.336ZMay 16 04:16:50.300 DEBG [sc] ox waiting for prompt
6542026-05-16T04:16:50.336ZMay 16 04:16:50.311 DEBG [sc] ox: logging in
6552026-05-16T04:16:50.410ZMay 16 04:16:50.398 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
6562026-05-16T04:16:54.393ZMay 16 04:16:54.381 DEBG [sc] cr2: starting
6572026-05-16T04:16:54.394ZMay 16 04:16:54.381 DEBG [sc] cr2: connecting to [::1]:56614
6582026-05-16T04:16:54.419ZMay 16 04:16:54.382 DEBG [sc] cr2 waiting for prompt
6592026-05-16T04:16:54.419ZMay 16 04:16:54.392 DEBG [sc] cr2: logging in
6602026-05-16T04:16:54.525ZMay 16 04:16:54.514 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6612026-05-16T04:16:56.656ZMay 16 04:16:56.644 INFO cr2: executing eos script show version
6622026-05-16T04:16:56.656ZMay 16 04:16:56.644 DEBG [sc] cr2: starting
6632026-05-16T04:16:56.656ZMay 16 04:16:56.644 DEBG [sc] cr2: connecting to [::1]:56614
6642026-05-16T04:16:56.680ZMay 16 04:16:56.644 DEBG [sc] cr2 waiting for prompt
6652026-05-16T04:16:56.680ZMay 16 04:16:56.655 DEBG [sc] cr2: logging in
6662026-05-16T04:16:56.821ZMay 16 04:16:56.809 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6672026-05-16T04:16:59.160ZMay 16 04:16:59.148 DEBG [sc] cr2: starting
6682026-05-16T04:16:59.160ZMay 16 04:16:59.148 DEBG [sc] cr2: connecting to [::1]:56614
6692026-05-16T04:16:59.185ZMay 16 04:16:59.149 DEBG [sc] cr2 waiting for prompt
6702026-05-16T04:16:59.185ZMay 16 04:16:59.159 DEBG [sc] cr2: logging in
6712026-05-16T04:16:59.336ZMay 16 04:16:59.324 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6722026-05-16T04:17:01.495ZMay 16 04:17:01.482 INFO cr2: executing eos script show version
6732026-05-16T04:17:01.495ZMay 16 04:17:01.482 DEBG [sc] cr2: starting
6742026-05-16T04:17:01.495ZMay 16 04:17:01.482 DEBG [sc] cr2: connecting to [::1]:56614
6752026-05-16T04:17:01.519ZMay 16 04:17:01.483 DEBG [sc] cr2 waiting for prompt
6762026-05-16T04:17:01.519ZMay 16 04:17:01.493 DEBG [sc] cr2: logging in
6772026-05-16T04:17:01.659ZMay 16 04:17:01.647 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6782026-05-16T04:17:04.132ZMay 16 04:17:04.120 DEBG [sc] cr2: starting
6792026-05-16T04:17:04.132ZMay 16 04:17:04.120 DEBG [sc] cr2: connecting to [::1]:56614
6802026-05-16T04:17:04.157ZMay 16 04:17:04.121 DEBG [sc] cr2 waiting for prompt
6812026-05-16T04:17:04.157ZMay 16 04:17:04.131 DEBG [sc] cr2: logging in
6822026-05-16T04:17:04.286ZMay 16 04:17:04.274 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6832026-05-16T04:17:06.397ZMay 16 04:17:06.385 INFO cr2: executing eos script show version
6842026-05-16T04:17:06.398ZMay 16 04:17:06.386 DEBG [sc] cr2: starting
6852026-05-16T04:17:06.398ZMay 16 04:17:06.386 DEBG [sc] cr2: connecting to [::1]:56614
6862026-05-16T04:17:06.422ZMay 16 04:17:06.386 DEBG [sc] cr2 waiting for prompt
6872026-05-16T04:17:06.422ZMay 16 04:17:06.396 DEBG [sc] cr2: logging in
6882026-05-16T04:17:06.562ZMay 16 04:17:06.550 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6892026-05-16T04:17:08.850ZMay 16 04:17:08.838 INFO cr2: executing eos script
6902026-05-16T04:17:08.850Z enable
6912026-05-16T04:17:08.850Z configure
6922026-05-16T04:17:08.850Z ip routing
6932026-05-16T04:17:08.850Z ipv6 unicast-routing
6942026-05-16T04:17:08.850Z interface Ethernet1
6952026-05-16T04:17:08.850Z no switchport
6962026-05-16T04:17:08.850Z ip address 10.0.1.2/24
6972026-05-16T04:17:08.850Z ipv6 enable
6982026-05-16T04:17:08.850Z ipv6 address fd00:2::2/64
6992026-05-16T04:17:08.850Z bfd interval 300 min-rx 300 multiplier 3
7002026-05-16T04:17:08.850Z exit
7012026-05-16T04:17:08.851Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7022026-05-16T04:17:08.851Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7032026-05-16T04:17:08.851Z exit
7042026-05-16T04:17:08.851Z
7052026-05-16T04:17:08.851ZMay 16 04:17:08.838 DEBG [sc] cr2: starting
7062026-05-16T04:17:08.851ZMay 16 04:17:08.838 DEBG [sc] cr2: connecting to [::1]:56614
7072026-05-16T04:17:08.876ZMay 16 04:17:08.839 DEBG [sc] cr2 waiting for prompt
7082026-05-16T04:17:08.876ZMay 16 04:17:08.850 DEBG [sc] cr2: logging in
7092026-05-16T04:17:09.016ZMay 16 04:17:09.003 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
7102026-05-16T04:17:09.016Z enable
7112026-05-16T04:17:09.016Z configure
7122026-05-16T04:17:09.016Z ip routing
7132026-05-16T04:17:09.016Z ipv6 unicast-routing
7142026-05-16T04:17:09.016Z interface Ethernet1
7152026-05-16T04:17:09.016Z no switchport
7162026-05-16T04:17:09.016Z ip address 10.0.1.2/24
7172026-05-16T04:17:09.016Z ipv6 enable
7182026-05-16T04:17:09.016Z ipv6 address fd00:2::2/64
7192026-05-16T04:17:09.016Z bfd interval 300 min-rx 300 multiplier 3
7202026-05-16T04:17:09.016Z exit
7212026-05-16T04:17:09.016Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7222026-05-16T04:17:09.016Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7232026-05-16T04:17:09.016Z exit
7242026-05-16T04:17:09.016Z '`
7252026-05-16T04:17:21.785ZMay 16 04:17:21.773 INFO cr1: enabling frr daemon bfdd
7262026-05-16T04:17:21.785ZMay 16 04:17:21.773 DEBG [sc] cr1: starting
7272026-05-16T04:17:21.785ZMay 16 04:17:21.773 DEBG [sc] cr1: connecting to [::1]:56852
7282026-05-16T04:17:21.810ZMay 16 04:17:21.774 DEBG [sc] cr1 waiting for prompt
7292026-05-16T04:17:21.810ZMay 16 04:17:21.785 DEBG [sc] cr1: logging in
7302026-05-16T04:17:21.940ZMay 16 04:17:21.928 DEBG [sc] cr1: executing command `sed -i 's/bfdd=no/bfdd=yes/g' /etc/frr/daemons`
7312026-05-16T04:17:24.030ZMay 16 04:17:24.018 DEBG [sc] cr1: starting
7322026-05-16T04:17:24.030ZMay 16 04:17:24.018 DEBG [sc] cr1: connecting to [::1]:56852
7332026-05-16T04:17:24.054ZMay 16 04:17:24.018 DEBG [sc] cr1 waiting for prompt
7342026-05-16T04:17:24.054ZMay 16 04:17:24.029 DEBG [sc] cr1: logging in
7352026-05-16T04:17:24.173ZMay 16 04:17:24.162 DEBG [sc] cr1: executing command `systemctl restart frr`
7362026-05-16T04:17:31.778ZMay 16 04:17:31.759 INFO cr1: executing frr script
7372026-05-16T04:17:31.778Z configure
7382026-05-16T04:17:31.778Z interface enp0s8
7392026-05-16T04:17:31.778Z ip address 10.0.0.2/24
7402026-05-16T04:17:31.778Z ipv6 address fd00:1::2/64
7412026-05-16T04:17:31.778Z no shutdown
7422026-05-16T04:17:31.778Z exit
7432026-05-16T04:17:31.778Z bfd
7442026-05-16T04:17:31.778Z peer 10.0.0.1 local-address 10.0.0.2
7452026-05-16T04:17:31.778Z detect-multiplier 3
7462026-05-16T04:17:31.778Z receive-interval 300
7472026-05-16T04:17:31.778Z transmit-interval 300
7482026-05-16T04:17:31.778Z no shutdown
7492026-05-16T04:17:31.779Z exit
7502026-05-16T04:17:31.779Z peer fd00:1::1 local-address fd00:1::2
7512026-05-16T04:17:31.779Z detect-multiplier 3
7522026-05-16T04:17:31.779Z receive-interval 300
7532026-05-16T04:17:31.779Z transmit-interval 300
7542026-05-16T04:17:31.779Z no shutdown
7552026-05-16T04:17:31.779Z exit
7562026-05-16T04:17:31.779Z exit
7572026-05-16T04:17:31.779Z
7582026-05-16T04:17:31.779ZMay 16 04:17:31.759 DEBG [sc] cr1: starting
7592026-05-16T04:17:31.779ZMay 16 04:17:31.759 DEBG [sc] cr1: connecting to [::1]:56852
7602026-05-16T04:17:31.779ZMay 16 04:17:31.760 DEBG [sc] cr1 waiting for prompt
7612026-05-16T04:17:31.803ZMay 16 04:17:31.771 DEBG [sc] cr1: logging in
7622026-05-16T04:17:31.916ZMay 16 04:17:31.904 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 ' '`
7632026-05-16T04:18:37.732ZMay 16 04:18:37.720 DEBG [sc] ox: starting
7642026-05-16T04:18:37.732ZMay 16 04:18:37.720 DEBG [sc] ox: connecting to [::1]:53488
7652026-05-16T04:18:37.757ZMay 16 04:18:37.720 DEBG [sc] ox waiting for prompt
7662026-05-16T04:18:37.758ZMay 16 04:18:37.731 DEBG [sc] ox: logging in
7672026-05-16T04:18:37.821ZMay 16 04:18:37.809 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
7682026-05-16T04:18:38.177ZMay 16 04:18:38.164 DEBG [sc] ox: starting
7692026-05-16T04:18:38.177ZMay 16 04:18:38.164 DEBG [sc] ox: connecting to [::1]:53488
7702026-05-16T04:18:38.201ZMay 16 04:18:38.165 DEBG [sc] ox waiting for prompt
7712026-05-16T04:18:38.201ZMay 16 04:18:38.176 DEBG [sc] ox: logging in
7722026-05-16T04:18:38.265ZMay 16 04:18:38.253 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7732026-05-16T04:18:38.321ZMay 16 04:18:38.309 DEBG [sc] ox: starting
7742026-05-16T04:18:38.321ZMay 16 04:18:38.309 DEBG [sc] ox: connecting to [::1]:53488
7752026-05-16T04:18:38.345ZMay 16 04:18:38.310 DEBG [sc] ox waiting for prompt
7762026-05-16T04:18:38.345ZMay 16 04:18:38.319 DEBG [sc] ox: logging in
7772026-05-16T04:18:38.409ZMay 16 04:18:38.397 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7782026-05-16T04:18:39.432ZMay 16 04:18:39.420 DEBG [sc] ox: starting
7792026-05-16T04:18:39.432ZMay 16 04:18:39.420 DEBG [sc] ox: connecting to [::1]:53488
7802026-05-16T04:18:39.457ZMay 16 04:18:39.420 DEBG [sc] ox waiting for prompt
7812026-05-16T04:18:39.457ZMay 16 04:18:39.420 DEBG [sc] ox: logging in
7822026-05-16T04:18:39.509ZMay 16 04:18:39.497 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7832026-05-16T04:18:39.900ZMay 16 04:18:39.888 DEBG [sc] ox: starting
7842026-05-16T04:18:39.900ZMay 16 04:18:39.888 DEBG [sc] ox: connecting to [::1]:53488
7852026-05-16T04:18:39.925ZMay 16 04:18:39.889 DEBG [sc] ox waiting for prompt
7862026-05-16T04:18:39.925ZMay 16 04:18:39.900 DEBG [sc] ox: logging in
7872026-05-16T04:18:40.000ZMay 16 04:18:39.988 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
7882026-05-16T04:18:40.067ZMay 16 04:18:40.055 DEBG [sc] ox: starting
7892026-05-16T04:18:40.067ZMay 16 04:18:40.055 DEBG [sc] ox: connecting to [::1]:53488
7902026-05-16T04:18:40.091ZMay 16 04:18:40.056 DEBG [sc] ox waiting for prompt
7912026-05-16T04:18:40.091ZMay 16 04:18:40.065 DEBG [sc] ox: logging in
7922026-05-16T04:18:40.166ZMay 16 04:18:40.154 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
7932026-05-16T04:18:40.232ZMay 16 04:18:40.220 DEBG [sc] ox: starting
7942026-05-16T04:18:40.232ZMay 16 04:18:40.220 DEBG [sc] ox: connecting to [::1]:53488
7952026-05-16T04:18:40.256ZMay 16 04:18:40.220 DEBG [sc] ox waiting for prompt
7962026-05-16T04:18:40.256ZMay 16 04:18:40.231 DEBG [sc] ox: logging in
7972026-05-16T04:18:40.321ZMay 16 04:18:40.309 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.0.1/24 tfportqsfp0_0/v4`
7982026-05-16T04:18:40.804ZMay 16 04:18:40.792 DEBG [sc] ox: starting
7992026-05-16T04:18:40.805ZMay 16 04:18:40.792 DEBG [sc] ox: connecting to [::1]:53488
8002026-05-16T04:18:40.829ZMay 16 04:18:40.793 DEBG [sc] ox waiting for prompt
8012026-05-16T04:18:40.829ZMay 16 04:18:40.804 DEBG [sc] ox: logging in
8022026-05-16T04:18:40.904ZMay 16 04:18:40.892 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v4 -p -o addr`
8032026-05-16T04:18:40.970ZMay 16 04:18:40.958 DEBG [sc] ox: starting
8042026-05-16T04:18:40.970ZMay 16 04:18:40.958 DEBG [sc] ox: connecting to [::1]:53488
8052026-05-16T04:18:40.994ZMay 16 04:18:40.958 DEBG [sc] ox waiting for prompt
8062026-05-16T04:18:40.995ZMay 16 04:18:40.969 DEBG [sc] ox: logging in
8072026-05-16T04:18:41.069ZMay 16 04:18:41.057 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:1::1/64 tfportqsfp0_0/v6`
8082026-05-16T04:18:41.582ZMay 16 04:18:41.569 DEBG [sc] ox: starting
8092026-05-16T04:18:41.582ZMay 16 04:18:41.570 DEBG [sc] ox: connecting to [::1]:53488
8102026-05-16T04:18:41.606ZMay 16 04:18:41.570 DEBG [sc] ox waiting for prompt
8112026-05-16T04:18:41.606ZMay 16 04:18:41.580 DEBG [sc] ox: logging in
8122026-05-16T04:18:41.670ZMay 16 04:18:41.658 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v6 -p -o addr`
8132026-05-16T04:18:41.725ZMay 16 04:18:41.713 DEBG [sc] ox: starting
8142026-05-16T04:18:41.725ZMay 16 04:18:41.713 DEBG [sc] ox: connecting to [::1]:53488
8152026-05-16T04:18:41.750ZMay 16 04:18:41.714 DEBG [sc] ox waiting for prompt
8162026-05-16T04:18:41.750ZMay 16 04:18:41.724 DEBG [sc] ox: logging in
8172026-05-16T04:18:41.814ZMay 16 04:18:41.802 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
8182026-05-16T04:18:41.869ZMay 16 04:18:41.857 DEBG [sc] ox: starting
8192026-05-16T04:18:41.869ZMay 16 04:18:41.857 DEBG [sc] ox: connecting to [::1]:53488
8202026-05-16T04:18:41.893ZMay 16 04:18:41.858 DEBG [sc] ox waiting for prompt
8212026-05-16T04:18:41.893ZMay 16 04:18:41.867 DEBG [sc] ox: logging in
8222026-05-16T04:18:41.957ZMay 16 04:18:41.945 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
8232026-05-16T04:18:42.012ZMay 16 04:18:42.000 DEBG [sc] ox: starting
8242026-05-16T04:18:42.012ZMay 16 04:18:42.000 DEBG [sc] ox: connecting to [::1]:53488
8252026-05-16T04:18:42.036ZMay 16 04:18:42.000 DEBG [sc] ox waiting for prompt
8262026-05-16T04:18:42.036ZMay 16 04:18:42.011 DEBG [sc] ox: logging in
8272026-05-16T04:18:42.099ZMay 16 04:18:42.087 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.1.1/24 tfportqsfp1_0/v4`
8282026-05-16T04:18:42.763ZMay 16 04:18:42.751 DEBG [sc] ox: starting
8292026-05-16T04:18:42.763ZMay 16 04:18:42.751 DEBG [sc] ox: connecting to [::1]:53488
8302026-05-16T04:18:42.787ZMay 16 04:18:42.752 DEBG [sc] ox waiting for prompt
8312026-05-16T04:18:42.787ZMay 16 04:18:42.762 DEBG [sc] ox: logging in
8322026-05-16T04:18:42.851ZMay 16 04:18:42.839 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v4 -p -o addr`
8332026-05-16T04:18:42.907ZMay 16 04:18:42.895 DEBG [sc] ox: starting
8342026-05-16T04:18:42.907ZMay 16 04:18:42.895 DEBG [sc] ox: connecting to [::1]:53488
8352026-05-16T04:18:42.931ZMay 16 04:18:42.896 DEBG [sc] ox waiting for prompt
8362026-05-16T04:18:42.931ZMay 16 04:18:42.906 DEBG [sc] ox: logging in
8372026-05-16T04:18:42.994ZMay 16 04:18:42.982 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:2::1/64 tfportqsfp1_0/v6`
8382026-05-16T04:18:43.281ZMay 16 04:18:43.269 DEBG [sc] ox: starting
8392026-05-16T04:18:43.281ZMay 16 04:18:43.269 DEBG [sc] ox: connecting to [::1]:53488
8402026-05-16T04:18:43.305ZMay 16 04:18:43.269 DEBG [sc] ox waiting for prompt
8412026-05-16T04:18:43.305ZMay 16 04:18:43.280 DEBG [sc] ox: logging in
8422026-05-16T04:18:43.369ZMay 16 04:18:43.357 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v6 -p -o addr`
8432026-05-16T04:18:43.424ZMay 16 04:18:43.412 DEBG [sc] ox: starting
8442026-05-16T04:18:43.424ZMay 16 04:18:43.412 DEBG [sc] ox: connecting to [::1]:53488
8452026-05-16T04:18:43.425ZMay 16 04:18:43.412 DEBG [sc] ox waiting for prompt
8462026-05-16T04:18:43.460ZMay 16 04:18:43.422 DEBG [sc] ox: logging in
8472026-05-16T04:18:43.522ZMay 16 04:18:43.510 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
8482026-05-16T04:18:43.578ZMay 16 04:18:43.566 DEBG [sc] ox: starting
8492026-05-16T04:18:43.578ZMay 16 04:18:43.566 DEBG [sc] ox: connecting to [::1]:53488
8502026-05-16T04:18:43.602ZMay 16 04:18:43.566 DEBG [sc] ox waiting for prompt
8512026-05-16T04:18:43.602ZMay 16 04:18:43.576 DEBG [sc] ox: logging in
8522026-05-16T04:18:43.665ZMay 16 04:18:43.653 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
8532026-05-16T04:18:43.725ZMay 16 04:18:43.713 INFO installing static v4 route 192.168.100.0/24
8542026-05-16T04:18:43.749ZMay 16 04:18:43.714 INFO installing static v6 route fd01::/64
8552026-05-16T04:18:43.749ZMay 16 04:18:43.714 INFO adding BFD peers for cr1 and cr2 (dual-stack)
8562026-05-16T04:18:43.749ZMay 16 04:18:43.717 INFO phase 1: both peers up
8572026-05-16T04:18:44.733ZMay 16 04:18:44.721 INFO cr1: executing frr script show bfd peers json
8582026-05-16T04:18:44.733ZMay 16 04:18:44.721 DEBG [sc] cr1: starting
8592026-05-16T04:18:44.734ZMay 16 04:18:44.721 DEBG [sc] cr1: connecting to [::1]:56852
8602026-05-16T04:18:44.758ZMay 16 04:18:44.722 DEBG [sc] cr1 waiting for prompt
8612026-05-16T04:18:44.758ZMay 16 04:18:44.733 DEBG [sc] cr1: logging in
8622026-05-16T04:18:45.095ZMay 16 04:18:45.083 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8632026-05-16T04:18:47.245ZMay 16 04:18:47.233 INFO cr1: executing frr script show bfd peers json
8642026-05-16T04:18:47.245ZMay 16 04:18:47.233 DEBG [sc] cr1: starting
8652026-05-16T04:18:47.245ZMay 16 04:18:47.233 DEBG [sc] cr1: connecting to [::1]:56852
8662026-05-16T04:18:47.270ZMay 16 04:18:47.234 DEBG [sc] cr1 waiting for prompt
8672026-05-16T04:18:47.270ZMay 16 04:18:47.243 DEBG [sc] cr1: logging in
8682026-05-16T04:18:47.389ZMay 16 04:18:47.377 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8692026-05-16T04:18:49.528ZMay 16 04:18:49.516 INFO cr2: executing eos script show bfd peers | json
8702026-05-16T04:18:49.528ZMay 16 04:18:49.516 DEBG [sc] cr2: starting
8712026-05-16T04:18:49.528ZMay 16 04:18:49.516 DEBG [sc] cr2: connecting to [::1]:56614
8722026-05-16T04:18:49.552ZMay 16 04:18:49.517 DEBG [sc] cr2 waiting for prompt
8732026-05-16T04:18:49.553ZMay 16 04:18:49.528 DEBG [sc] cr2: logging in
8742026-05-16T04:18:49.864ZMay 16 04:18:49.852 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8752026-05-16T04:18:52.222ZMay 16 04:18:52.210 INFO cr2: executing eos script show bfd peers | json
8762026-05-16T04:18:52.222ZMay 16 04:18:52.210 DEBG [sc] cr2: starting
8772026-05-16T04:18:52.222ZMay 16 04:18:52.210 DEBG [sc] cr2: connecting to [::1]:56614
8782026-05-16T04:18:52.246ZMay 16 04:18:52.211 DEBG [sc] cr2 waiting for prompt
8792026-05-16T04:18:52.246ZMay 16 04:18:52.221 DEBG [sc] cr2: logging in
8802026-05-16T04:18:52.365ZMay 16 04:18:52.353 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8812026-05-16T04:18:54.732ZMay 16 04:18:54.720 INFO phase 2: pause bfdd on cr1
8822026-05-16T04:18:54.732ZMay 16 04:18:54.720 INFO cr1: pausing frr bfdd
8832026-05-16T04:18:54.732ZMay 16 04:18:54.720 DEBG [sc] cr1: starting
8842026-05-16T04:18:54.732ZMay 16 04:18:54.720 DEBG [sc] cr1: connecting to [::1]:56852
8852026-05-16T04:18:54.756ZMay 16 04:18:54.721 DEBG [sc] cr1 waiting for prompt
8862026-05-16T04:18:54.756ZMay 16 04:18:54.732 DEBG [sc] cr1: logging in
8872026-05-16T04:18:54.877ZMay 16 04:18:54.865 DEBG [sc] cr1: executing command `pkill -STOP bfdd`
8882026-05-16T04:18:56.971ZMay 16 04:18:56.959 INFO cr2: executing eos script show bfd peers | json
8892026-05-16T04:18:56.971ZMay 16 04:18:56.959 DEBG [sc] cr2: starting
8902026-05-16T04:18:56.995ZMay 16 04:18:56.959 DEBG [sc] cr2: connecting to [::1]:56614
8912026-05-16T04:18:56.995ZMay 16 04:18:56.960 DEBG [sc] cr2 waiting for prompt
8922026-05-16T04:18:56.995ZMay 16 04:18:56.971 DEBG [sc] cr2: logging in
8932026-05-16T04:18:57.104ZMay 16 04:18:57.092 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8942026-05-16T04:18:59.438ZMay 16 04:18:59.426 INFO cr2: executing eos script show bfd peers | json
8952026-05-16T04:18:59.438ZMay 16 04:18:59.426 DEBG [sc] cr2: starting
8962026-05-16T04:18:59.463ZMay 16 04:18:59.426 DEBG [sc] cr2: connecting to [::1]:56614
8972026-05-16T04:18:59.463ZMay 16 04:18:59.427 DEBG [sc] cr2 waiting for prompt
8982026-05-16T04:18:59.463ZMay 16 04:18:59.437 DEBG [sc] cr2: logging in
8992026-05-16T04:18:59.583ZMay 16 04:18:59.571 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9002026-05-16T04:19:01.963ZMay 16 04:19:01.951 INFO phase 3: pause ceos on cr2
9012026-05-16T04:19:01.963ZMay 16 04:19:01.951 INFO cr2: pausing ceos
9022026-05-16T04:19:01.963ZMay 16 04:19:01.951 DEBG [sc] cr2: starting
9032026-05-16T04:19:01.963ZMay 16 04:19:01.951 DEBG [sc] cr2: connecting to [::1]:56614
9042026-05-16T04:19:01.988ZMay 16 04:19:01.952 DEBG [sc] cr2 waiting for prompt
9052026-05-16T04:19:01.988ZMay 16 04:19:01.961 DEBG [sc] cr2: logging in
9062026-05-16T04:19:02.095ZMay 16 04:19:02.083 DEBG [sc] cr2: executing command `docker pause ceos`
9072026-05-16T04:19:04.197ZMay 16 04:19:04.184 INFO phase 4: resume bfdd on cr1
9082026-05-16T04:19:04.197ZMay 16 04:19:04.184 INFO cr1: resuming frr bfdd
9092026-05-16T04:19:04.197ZMay 16 04:19:04.184 DEBG [sc] cr1: starting
9102026-05-16T04:19:04.197ZMay 16 04:19:04.184 DEBG [sc] cr1: connecting to [::1]:56852
9112026-05-16T04:19:04.222ZMay 16 04:19:04.185 DEBG [sc] cr1 waiting for prompt
9122026-05-16T04:19:04.222ZMay 16 04:19:04.196 DEBG [sc] cr1: logging in
9132026-05-16T04:19:04.330ZMay 16 04:19:04.318 DEBG [sc] cr1: executing command `pkill -CONT bfdd`
9142026-05-16T04:19:06.420ZMay 16 04:19:06.408 INFO cr1: executing frr script show bfd peers json
9152026-05-16T04:19:06.420ZMay 16 04:19:06.408 DEBG [sc] cr1: starting
9162026-05-16T04:19:06.420ZMay 16 04:19:06.408 DEBG [sc] cr1: connecting to [::1]:56852
9172026-05-16T04:19:06.444ZMay 16 04:19:06.409 DEBG [sc] cr1 waiting for prompt
9182026-05-16T04:19:06.444ZMay 16 04:19:06.417 DEBG [sc] cr1: logging in
9192026-05-16T04:19:06.550ZMay 16 04:19:06.538 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9202026-05-16T04:19:08.693ZMay 16 04:19:08.680 INFO cr1: executing frr script show bfd peers json
9212026-05-16T04:19:08.693ZMay 16 04:19:08.681 DEBG [sc] cr1: starting
9222026-05-16T04:19:08.693ZMay 16 04:19:08.681 DEBG [sc] cr1: connecting to [::1]:56852
9232026-05-16T04:19:08.717ZMay 16 04:19:08.681 DEBG [sc] cr1 waiting for prompt
9242026-05-16T04:19:08.717ZMay 16 04:19:08.691 DEBG [sc] cr1: logging in
9252026-05-16T04:19:08.837ZMay 16 04:19:08.825 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9262026-05-16T04:19:10.985ZMay 16 04:19:10.973 INFO phase 5: unpause ceos on cr2
9272026-05-16T04:19:10.985ZMay 16 04:19:10.973 INFO cr2: unpausing ceos
9282026-05-16T04:19:10.985ZMay 16 04:19:10.973 DEBG [sc] cr2: starting
9292026-05-16T04:19:10.986ZMay 16 04:19:10.973 DEBG [sc] cr2: connecting to [::1]:56614
9302026-05-16T04:19:11.010ZMay 16 04:19:10.974 DEBG [sc] cr2 waiting for prompt
9312026-05-16T04:19:11.010ZMay 16 04:19:10.985 DEBG [sc] cr2: logging in
9322026-05-16T04:19:11.119ZMay 16 04:19:11.107 DEBG [sc] cr2: executing command `docker unpause ceos`
9332026-05-16T04:19:13.226ZMay 16 04:19:13.212 INFO cr1: executing frr script show bfd peers json
9342026-05-16T04:19:13.226ZMay 16 04:19:13.212 DEBG [sc] cr1: starting
9352026-05-16T04:19:13.226ZMay 16 04:19:13.212 DEBG [sc] cr1: connecting to [::1]:56852
9362026-05-16T04:19:13.251ZMay 16 04:19:13.213 DEBG [sc] cr1 waiting for prompt
9372026-05-16T04:19:13.251ZMay 16 04:19:13.224 DEBG [sc] cr1: logging in
9382026-05-16T04:19:13.380ZMay 16 04:19:13.368 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9392026-05-16T04:19:15.513ZMay 16 04:19:15.500 INFO cr1: executing frr script show bfd peers json
9402026-05-16T04:19:15.513ZMay 16 04:19:15.500 DEBG [sc] cr1: starting
9412026-05-16T04:19:15.513ZMay 16 04:19:15.500 DEBG [sc] cr1: connecting to [::1]:56852
9422026-05-16T04:19:15.537ZMay 16 04:19:15.501 DEBG [sc] cr1 waiting for prompt
9432026-05-16T04:19:15.537ZMay 16 04:19:15.511 DEBG [sc] cr1: logging in
9442026-05-16T04:19:15.666ZMay 16 04:19:15.654 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9452026-05-16T04:19:17.804ZMay 16 04:19:17.792 INFO cr2: executing eos script show bfd peers | json
9462026-05-16T04:19:17.829ZMay 16 04:19:17.792 DEBG [sc] cr2: starting
9472026-05-16T04:19:17.829ZMay 16 04:19:17.792 DEBG [sc] cr2: connecting to [::1]:56614
9482026-05-16T04:19:17.829ZMay 16 04:19:17.793 DEBG [sc] cr2 waiting for prompt
9492026-05-16T04:19:17.829ZMay 16 04:19:17.804 DEBG [sc] cr2: logging in
9502026-05-16T04:19:17.960ZMay 16 04:19:17.948 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9512026-05-16T04:19:20.347ZMay 16 04:19:20.334 INFO cr2: executing eos script show bfd peers | json
9522026-05-16T04:19:20.347ZMay 16 04:19:20.334 DEBG [sc] cr2: starting
9532026-05-16T04:19:20.347ZMay 16 04:19:20.334 DEBG [sc] cr2: connecting to [::1]:56614
9542026-05-16T04:19:20.372ZMay 16 04:19:20.335 DEBG [sc] cr2 waiting for prompt
9552026-05-16T04:19:20.372ZMay 16 04:19:20.344 DEBG [sc] cr2: logging in
9562026-05-16T04:19:20.500ZMay 16 04:19:20.487 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9572026-05-16T04:19:22.889ZMay 16 04:19:22.877 INFO trio bfd static routing test passed 🎉
9582026-05-16T04:19:22.890ZMay 16 04:19:22.877 INFO destroying runner for deployment mgtriobfd
9592026-05-16T04:19:22.890ZMay 16 04:19:22.877 INFO destroying deployment mgtriobfd
9602026-05-16T04:19:22.890ZMay 16 04:19:22.877 INFO destroying nodes
9612026-05-16T04:19:22.992ZMay 16 04:19:22.980 INFO destroying links
9622026-05-16T04:19:22.992ZMay 16 04:19:22.980 INFO destroying link mgtriobfd_ox_sn_vnic0
9632026-05-16T04:19:23.017ZMay 16 04:19:22.982 INFO destroying link mgtriobfd_ox_sn_sim0
9642026-05-16T04:19:23.017ZMay 16 04:19:22.983 INFO destroying link mgtriobfd_cr1_vn_vnic0
9652026-05-16T04:19:23.997ZMay 16 04:19:23.985 INFO destroying link mgtriobfd_cr1_vn_sim0
9662026-05-16T04:19:24.022ZMay 16 04:19:23.986 INFO destroying link mgtriobfd_ox_sn_vnic1
9672026-05-16T04:19:24.022ZMay 16 04:19:23.986 INFO destroying link mgtriobfd_ox_sn_sim1
9682026-05-16T04:19:24.022ZMay 16 04:19:23.987 INFO destroying link mgtriobfd_cr2_vn_vnic0
9692026-05-16T04:19:24.022ZMay 16 04:19:23.988 INFO destroying link mgtriobfd_cr2_vn_sim0
9702026-05-16T04:19:24.022ZMay 16 04:19:23.989 INFO destroying external links
9712026-05-16T04:19:24.022ZMay 16 04:19:23.989 INFO destroying external link mgtriobfd_ox_vn_vnic2
9722026-05-16T04:19:24.022ZMay 16 04:19:23.989 INFO destroying external link mgtriobfd_cr1_vn_vnic1
9732026-05-16T04:19:24.022ZMay 16 04:19:23.990 INFO destroying external link mgtriobfd_cr2_vn_vnic1
9742026-05-16T04:19:24.022ZMay 16 04:19:23.991 INFO destroying images
9752026-05-16T04:19:24.473ZMay 16 04:19:24.461 INFO destroying workspace at .falcon
9762026-05-16T04:19:24.498Zprocess exited: duration 691687 ms, exit code 0
 
9772026-05-16T04:19:24.549Zfound 0 output files