01KS1DJ01AAYCZ95T3Y7H0MX90: falcon

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

Buildomat Job: 01KS1DJE4BFW6YXKG7ZRFNJJ0T

Tags:

Output:

SEQ GLOBAL TIME DETAILS
12026-05-20T01:00:11.981Zjob dependencies complete; ready to run (waiting for 13 m 39 s)
22026-05-20T01:03:28.473Zjob assigned to worker 01KS1EBEGWP9M34AMGPW9G34CZ [factory edgar, gimlet/BRM42220060/580] (queued for 3 m 16 s)
32026-05-20T01:03:29.413Zdownloading input: /input/build/work/debug/ddmadm
42026-05-20T01:04:21.855Zdownloaded input: /input/build/work/debug/ddmadm
52026-05-20T01:04:21.855Zdownloading input: /input/build/work/debug/ddmd
62026-05-20T01:05:09.395Zdownloaded input: /input/build/work/debug/ddmd
72026-05-20T01:05:09.434Zdownloading input: /input/build/work/debug/mgadm
82026-05-20T01:05:53.681Zdownloaded input: /input/build/work/debug/mgadm
92026-05-20T01:05:53.681Zdownloading input: /input/build/work/debug/mgd
102026-05-20T01:07:18.294Zdownloaded input: /input/build/work/debug/mgd
112026-05-20T01:07:18.328Zdownloading input: /input/build/work/release/ddmadm
122026-05-20T01:07:24.056Zdownloaded input: /input/build/work/release/ddmadm
132026-05-20T01:07:24.056Zdownloading input: /input/build/work/release/ddmd
142026-05-20T01:07:28.780Zdownloaded input: /input/build/work/release/ddmd
152026-05-20T01:07:28.780Zdownloading input: /input/build/work/release/falcon-lab
162026-05-20T01:07:31.786Zdownloaded input: /input/build/work/release/falcon-lab
172026-05-20T01:07:31.786Zdownloading input: /input/build/work/release/mgadm
182026-05-20T01:07:36.218Zdownloaded input: /input/build/work/release/mgadm
192026-05-20T01:07:36.218Zdownloading input: /input/build/work/release/mgd
202026-05-20T01:07:41.520Zdownloaded input: /input/build/work/release/mgd
212026-05-20T01:07:41.563Zdownloading input: /input/build-interop/work/testbed.tar.gz
222026-05-20T01:08:17.831Zdownloaded input: /input/build-interop/work/testbed.tar.gz
232026-05-20T01:08:17.831Zdownloading input: /input/build-interop/work/dhcp-server
242026-05-20T01:08:23.917Zdownloaded input: /input/build-interop/work/dhcp-server
 
252026-05-20T01:08:23.918Zstarting task 0: "setup"
262026-05-20T01:08:23.953Z++ uname -s
272026-05-20T01:08:23.953Z+ kern=SunOS
282026-05-20T01:08:23.953Z+ build_user=build
292026-05-20T01:08:23.953Z+ build_uid=12345
302026-05-20T01:08:23.953Z+ work_dir=/work
312026-05-20T01:08:23.953Z+ input_dir=/input
322026-05-20T01:08:23.953Z+ [[ 0 == 12345 ]]
332026-05-20T01:08:23.953Z+ case "$kern" in
342026-05-20T01:08:23.953Z+ groupadd -g 12345 build
352026-05-20T01:08:23.953Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
362026-05-20T01:08:25.950Z+ zfs create -o mountpoint=/work rpool/work
372026-05-20T01:08:26.038Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
382026-05-20T01:08:26.076Z+ home_fs=
392026-05-20T01:08:26.076Z+ [[ '' == autofs ]]
402026-05-20T01:08:26.076Z+ mkdir -p /home/build
412026-05-20T01:08:26.076Z+ chown build:build /home/build /work
422026-05-20T01:08:27.049Z+ chmod 0700 /home/build /work
432026-05-20T01:08:27.086Zprocess exited: duration 3138 ms, exit code 0
 
442026-05-20T01:08:27.154Zstarting task 1: "authentication"
452026-05-20T01:08:27.261Zprocess exited: duration 106 ms, exit code 0
 
462026-05-20T01:08:27.336Zstarting task 2: "build"
472026-05-20T01:08:27.376Z+ set -e
482026-05-20T01:08:27.376Z+ banner zpool
492026-05-20T01:08:27.376Z
502026-05-20T01:08:27.376Z ###### ##### #### #### #
512026-05-20T01:08:27.376Z # # # # # # # #
522026-05-20T01:08:27.377Z # # # # # # # #
532026-05-20T01:08:27.377Z # ##### # # # # #
542026-05-20T01:08:27.377Z # # # # # # #
552026-05-20T01:08:27.377Z ###### # #### #### ######
562026-05-20T01:08:27.377Z
572026-05-20T01:08:27.377Z++ pfexec diskinfo -pH
582026-05-20T01:08:27.377Z++ sort -k8 -n -r
592026-05-20T01:08:27.377Z++ head -1
602026-05-20T01:08:27.377Z++ awk '{print $2}'
612026-05-20T01:08:27.409Z+ DISK=c9t0014EE81000BC57Cd0
622026-05-20T01:08:27.409Z+ export DISK
632026-05-20T01:08:27.409Z+ pfexec zpool create -o ashift=12 -f cpool c9t0014EE81000BC57Cd0
642026-05-20T01:08:27.478Z+ pfexec zfs create -o mountpoint=/ci cpool/ci
652026-05-20T01:08:27.512Z++ curl -s http://catacomb.eng.oxide.computer:12346/trim-me
662026-05-20T01:08:27.689Z+ [[ true =~ true ]]
672026-05-20T01:08:27.690Z+ pfexec zpool trim cpool
682026-05-20T01:08:27.733Z++ zpool status -t cpool
692026-05-20T01:08:27.733Z+ [[ ! pool: cpool
702026-05-20T01:08:27.733Z state: ONLINE
712026-05-20T01:08:27.733Z scan: none requested
722026-05-20T01:08:27.733Zconfig:
732026-05-20T01:08:27.733Z
742026-05-20T01:08:27.733Z NAME STATE READ WRITE CKSUM
752026-05-20T01:08:27.733Z cpool ONLINE 0 0 0
762026-05-20T01:08:27.733Z c9t0014EE81000BC57Cd0 ONLINE 0 0 0 (1% trimmed, started at May 20, 2026 at 01:08:27 AM UTC)
772026-05-20T01:08:27.733Z
782026-05-20T01:08:27.733Zerrors: No known data errors =~ 100% ]]
792026-05-20T01:08:27.733Z+ sleep 10
802026-05-20T01:08:37.721Z++ zpool status -t cpool
812026-05-20T01:08:37.760Z+ [[ ! pool: cpool
822026-05-20T01:08:37.760Z state: ONLINE
832026-05-20T01:08:37.760Z scan: none requested
842026-05-20T01:08:37.760Zconfig:
852026-05-20T01:08:37.760Z
862026-05-20T01:08:37.760Z NAME STATE READ WRITE CKSUM
872026-05-20T01:08:37.760Z cpool ONLINE 0 0 0
882026-05-20T01:08:37.760Z c9t0014EE81000BC57Cd0 ONLINE 0 0 0 (71% trimmed, started at May 20, 2026 at 01:08:27 AM UTC)
892026-05-20T01:08:37.760Z
902026-05-20T01:08:37.760Zerrors: No known data errors =~ 100% ]]
912026-05-20T01:08:37.760Z+ sleep 10
922026-05-20T01:08:47.886Z++ zpool status -t cpool
932026-05-20T01:08:48.452Z+ [[ ! pool: cpool
942026-05-20T01:08:48.452Z state: ONLINE
952026-05-20T01:08:48.452Z scan: none requested
962026-05-20T01:08:48.452Zconfig:
972026-05-20T01:08:48.452Z
982026-05-20T01:08:48.452Z NAME STATE READ WRITE CKSUM
992026-05-20T01:08:48.452Z cpool ONLINE 0 0 0
1002026-05-20T01:08:48.452Z c9t0014EE81000BC57Cd0 ONLINE 0 0 0 (100% trimmed, completed at May 20, 2026 at 01:08:41 AM UTC)
1012026-05-20T01:08:48.452Z
1022026-05-20T01:08:48.452Zerrors: No known data errors =~ 100% ]]
1032026-05-20T01:08:48.452Z+ pfexec chown 12345 /ci
1042026-05-20T01:08:48.452Z+ cd /ci
1052026-05-20T01:08:48.453Z+ export FALCON_DATASET=cpool/falcon
1062026-05-20T01:08:48.453Z+ FALCON_DATASET=cpool/falcon
1072026-05-20T01:08:48.453Z+ banner setup
1082026-05-20T01:08:48.453Z
1092026-05-20T01:08:48.453Z #### ###### ##### # # #####
1102026-05-20T01:08:48.453Z # # # # # # #
1112026-05-20T01:08:48.453Z #### ##### # # # # #
1122026-05-20T01:08:48.453Z # # # # # #####
1132026-05-20T01:08:48.453Z # # # # # # #
1142026-05-20T01:08:48.453Z #### ###### # #### #
1152026-05-20T01:08:48.453Z
1162026-05-20T01:08:48.453Z+ cp /input/build-interop/work/dhcp-server .
1172026-05-20T01:08:48.453Z+ cp /input/build/work/release/falcon-lab .
1182026-05-20T01:08:48.453Z+ cp /input/build/work/release/mgd .
1192026-05-20T01:08:48.453Z+ cp /input/build/work/release/ddmd .
1202026-05-20T01:08:48.637Z+ chmod +x dhcp-server falcon-lab mgd ddmd
1212026-05-20T01:08:48.637Z+ mkdir -p cargo-bay
1222026-05-20T01:08:48.637Z+ mv mgd cargo-bay/
1232026-05-20T01:08:48.637Z+ mv ddmd cargo-bay/
1242026-05-20T01:08:48.637Z+ export EXT_INTERFACE=igb0
1252026-05-20T01:08:48.638Z+ EXT_INTERFACE=igb0
1262026-05-20T01:08:48.638Z++ bmat address ls -f extra -Ho first
1272026-05-20T01:08:48.638Z+ first=10.151.7.164
1282026-05-20T01:08:48.638Z++ bmat address ls -f extra -Ho last
1292026-05-20T01:08:48.638Z+ last=10.151.7.227
1302026-05-20T01:08:48.638Z++ bmat address ls -f extra -Ho gateway
1312026-05-20T01:08:48.638Z+ gw=10.151.7.1
1322026-05-20T01:08:48.638Z++ ipadm show-addr igb0/dhcp -po ADDR
1332026-05-20T01:08:48.638Z++ sed 's#/.*##g'
1342026-05-20T01:08:48.638Z+ server=10.151.7.100
1352026-05-20T01:08:48.638Z+ RUST_LOG=debug
1362026-05-20T01:08:48.638Z+ pfexec ./falcon-lab run trio-unnumbered
1372026-05-20T01:08:48.638Z+ pfexec ./dhcp-server 10.151.7.164 10.151.7.227 10.151.7.1 10.151.7.100
1382026-05-20T01:08:48.638ZMay 20 01:08:48.065 DEBG using default route interface igb0
1392026-05-20T01:08:48.638ZMay 20 01:08:48.065 DEBG using default route interface igb0
1402026-05-20T01:08:48.638ZMay 20 01:08:48.065 DEBG using default route interface igb0
1412026-05-20T01:08:48.638ZMay 20 01:08:48.065 INFO launching runner: deployment(mgtriou) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
1422026-05-20T01:08:48.638ZMay 20 01:08:48.065 INFO starting preflight for deployment mgtriou
1432026-05-20T01:08:48.638ZMay 20 01:08:48.065 INFO propolis-server binary not found
1442026-05-20T01:08:48.638ZMay 20 01:08:48.065 INFO downloading propolis server rev 36f20be9bb4c3b362029237f5feb6377c982395f, writing to .falcon/bin/propolis-server
1452026-05-20T01:08:54.698ZMay 20 01:08:54.621 INFO ovmf fd not found
1462026-05-20T01:08:54.698ZMay 20 01:08:54.621 INFO downloading ovmf
1472026-05-20T01:08:55.509ZMay 20 01:08:55.475 INFO base image for helios-2.9 does not exist, attempting to install
1482026-05-20T01:08:55.509ZMay 20 01:08:55.475 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/helios-2.9_0.raw.xz
1492026-05-20T01:10:22.513ZMay 20 01:10:21.428 INFO extracting image to /tmp/helios-2.9_0.raw
1502026-05-20T01:10:54.859ZMay 20 01:10:54.825 INFO creating zvol cpool/falcon/img/helios-2.9 of size 4508880896
1512026-05-20T01:10:54.921ZMay 20 01:10:54.873 INFO copying image data to zvol
1522026-05-20T01:11:07.477ZMay 20 01:11:07.459 INFO creating zfs snapshot cpool/falcon/img/helios-2.9@base
1532026-05-20T01:11:11.637ZMay 20 01:11:11.620 INFO base image for debian-13.2 does not exist, attempting to install
1542026-05-20T01:11:11.637ZMay 20 01:11:11.621 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz
1552026-05-20T01:11:41.468ZMay 20 01:11:41.443 INFO extracting image to /tmp/debian-13.2_0.raw
1562026-05-20T01:12:02.306ZMay 20 01:12:02.283 INFO creating zvol cpool/falcon/img/debian-13.2 of size 3221229568
1572026-05-20T01:12:02.344ZMay 20 01:12:02.308 INFO copying image data to zvol
1582026-05-20T01:12:09.564ZMay 20 01:12:09.547 INFO creating zfs snapshot cpool/falcon/img/debian-13.2@base
1592026-05-20T01:12:13.408ZMay 20 01:12:13.386 INFO base image for eos-4.35 does not exist, attempting to install
1602026-05-20T01:12:13.408ZMay 20 01:12:13.386 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz
1612026-05-20T01:13:14.285ZMay 20 01:13:14.263 INFO extracting image to /tmp/eos-4.35_0.raw
1622026-05-20T01:14:37.358ZMay 20 01:14:37.337 INFO creating zvol cpool/falcon/img/eos-4.35 of size 21474840576
1632026-05-20T01:14:37.391ZMay 20 01:14:37.363 INFO copying image data to zvol
1642026-05-20T01:15:26.620ZMay 20 01:15:26.603 INFO creating zfs snapshot cpool/falcon/img/eos-4.35@base
1652026-05-20T01:15:30.075ZMay 20 01:15:30.057 INFO creating links
1662026-05-20T01:15:30.075ZMay 20 01:15:30.057 DEBG destroying link mgtriou_ox_sn_vnic0
1672026-05-20T01:15:30.215ZMay 20 01:15:30.058 DEBG destroying link mgtriou_ox_sn_sim0
1682026-05-20T01:15:30.215ZMay 20 01:15:30.058 INFO creating simnet link 'mgtriou_ox_sn_sim0'
1692026-05-20T01:15:30.215ZMay 20 01:15:30.060 INFO creating vnic link 'mgtriou_ox_sn_vnic0'
1702026-05-20T01:15:30.215ZMay 20 01:15:30.067 DEBG link pair created
1712026-05-20T01:15:30.215ZMay 20 01:15:30.067 DEBG destroying link mgtriou_cr1_vn_vnic0
1722026-05-20T01:15:30.215ZMay 20 01:15:30.067 DEBG destroying link mgtriou_cr1_vn_sim0
1732026-05-20T01:15:30.215ZMay 20 01:15:30.067 INFO creating simnet link 'mgtriou_cr1_vn_sim0'
1742026-05-20T01:15:30.215ZMay 20 01:15:30.069 INFO creating vnic link 'mgtriou_cr1_vn_vnic0'
1752026-05-20T01:15:30.215ZMay 20 01:15:30.075 DEBG link pair created
1762026-05-20T01:15:30.215ZMay 20 01:15:30.075 DEBG destroying link mgtriou_ox_sn_vnic1
1772026-05-20T01:15:30.215ZMay 20 01:15:30.075 DEBG destroying link mgtriou_ox_sn_sim1
1782026-05-20T01:15:30.215ZMay 20 01:15:30.075 INFO creating simnet link 'mgtriou_ox_sn_sim1'
1792026-05-20T01:15:30.215ZMay 20 01:15:30.077 INFO creating vnic link 'mgtriou_ox_sn_vnic1'
1802026-05-20T01:15:30.215ZMay 20 01:15:30.084 DEBG link pair created
1812026-05-20T01:15:30.215ZMay 20 01:15:30.084 DEBG destroying link mgtriou_cr2_vn_vnic0
1822026-05-20T01:15:30.215ZMay 20 01:15:30.084 DEBG destroying link mgtriou_cr2_vn_sim0
1832026-05-20T01:15:30.215ZMay 20 01:15:30.084 INFO creating simnet link 'mgtriou_cr2_vn_sim0'
1842026-05-20T01:15:30.215ZMay 20 01:15:30.085 INFO creating vnic link 'mgtriou_cr2_vn_vnic0'
1852026-05-20T01:15:30.324ZMay 20 01:15:30.092 DEBG link pair created
1862026-05-20T01:15:30.324ZMay 20 01:15:30.092 INFO creating external links
1872026-05-20T01:15:30.324ZMay 20 01:15:30.092 DEBG destroying external link mgtriou_ox_vn_vnic2
1882026-05-20T01:15:30.324ZMay 20 01:15:30.092 INFO creating external link mgtriou_ox_vn_vnic2
1892026-05-20T01:15:30.324ZMay 20 01:15:30.094 DEBG external link mgtriou_ox_vn_vnic2@igb0 created
1902026-05-20T01:15:30.324ZMay 20 01:15:30.094 DEBG destroying external link mgtriou_cr1_vn_vnic1
1912026-05-20T01:15:30.324ZMay 20 01:15:30.094 INFO creating external link mgtriou_cr1_vn_vnic1
1922026-05-20T01:15:30.324ZMay 20 01:15:30.095 DEBG external link mgtriou_cr1_vn_vnic1@igb0 created
1932026-05-20T01:15:30.324ZMay 20 01:15:30.095 DEBG destroying external link mgtriou_cr2_vn_vnic1
1942026-05-20T01:15:30.324ZMay 20 01:15:30.095 INFO creating external link mgtriou_cr2_vn_vnic1
1952026-05-20T01:15:30.324ZMay 20 01:15:30.096 DEBG external link mgtriou_cr2_vn_vnic1@igb0 created
1962026-05-20T01:15:30.324ZMay 20 01:15:30.096 INFO creating nodes
1972026-05-20T01:15:30.324ZMay 20 01:15:30.096 INFO ox: launching node
1982026-05-20T01:15:30.324ZMay 20 01:15:30.099 INFO cr1: launching node
1992026-05-20T01:15:30.324ZMay 20 01:15:30.101 INFO cr2: launching node
2002026-05-20T01:15:30.324ZMay 20 01:15:30.126 INFO launched instance ox with pid 849 on port 59741
2012026-05-20T01:15:30.324ZMay 20 01:15:30.126 INFO ox: instance ensure
2022026-05-20T01:15:30.324ZMay 20 01:15:30.126 INFO launched instance cr1 with pid 850 on port 50879
2032026-05-20T01:15:30.324ZMay 20 01:15:30.126 INFO cr1: instance ensure
2042026-05-20T01:15:30.324ZMay 20 01:15:30.127 INFO launched instance cr2 with pid 851 on port 54330
2052026-05-20T01:15:30.324ZMay 20 01:15:30.127 INFO cr2: instance ensure
2062026-05-20T01:15:32.408ZMay 20 01:15:32.390 INFO cr2: instance ensure completed after 0 retries
2072026-05-20T01:15:32.408ZMay 20 01:15:32.390 INFO cr2: instance run
2082026-05-20T01:15:32.444ZMay 20 01:15:32.390 DEBG [sc] cr2: starting
2092026-05-20T01:15:32.444ZMay 20 01:15:32.390 DEBG [sc] cr2: connecting to [::1]:54330
2102026-05-20T01:15:32.444ZMay 20 01:15:32.391 DEBG [sc] cr2 waiting for prompt
2112026-05-20T01:15:32.478ZMay 20 01:15:32.424 INFO cr1: instance ensure completed after 0 retries
2122026-05-20T01:15:32.478ZMay 20 01:15:32.424 INFO cr1: instance run
2132026-05-20T01:15:32.478ZMay 20 01:15:32.425 DEBG [sc] cr1: starting
2142026-05-20T01:15:32.478ZMay 20 01:15:32.425 DEBG [sc] cr1: connecting to [::1]:50879
2152026-05-20T01:15:32.478ZMay 20 01:15:32.426 DEBG [sc] cr1 waiting for prompt
2162026-05-20T01:15:32.478ZMay 20 01:15:32.459 INFO ox: instance ensure completed after 0 retries
2172026-05-20T01:15:32.478ZMay 20 01:15:32.459 INFO ox: instance run
2182026-05-20T01:15:32.478ZMay 20 01:15:32.460 DEBG [sc] ox: starting
2192026-05-20T01:15:32.478ZMay 20 01:15:32.460 DEBG [sc] ox: connecting to [::1]:59741
2202026-05-20T01:15:32.512ZMay 20 01:15:32.460 DEBG [sc] ox waiting for prompt
2212026-05-20T01:15:49.674ZMay 20 01:15:49.430 DEBG [sc] cr1: logging in
2222026-05-20T01:15:49.839ZMay 20 01:15:49.819 INFO cr1: mounting /opt/cargo-bay
2232026-05-20T01:15:49.839ZMay 20 01:15:49.819 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2242026-05-20T01:15:50.118ZMay 20 01:15:49.841 DEBG [sc] cr1: executing command `cd`
2252026-05-20T01:15:50.118ZMay 20 01:15:49.851 INFO cr1: finished mounting /opt/cargo-bay
2262026-05-20T01:15:50.118ZMay 20 01:15:49.851 DEBG [sc] cr1: executing command `hostname cr1`
2272026-05-20T01:15:50.490ZMay 20 01:15:49.862 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
2282026-05-20T01:15:50.490ZMay 20 01:15:49.873 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
2292026-05-20T01:15:50.490ZMay 20 01:15:49.885 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
2302026-05-20T01:15:50.490ZMay 20 01:15:49.896 INFO cr1: logging out
2312026-05-20T01:15:52.022ZMay 20 01:15:51.959 INFO cr1: logged out
2322026-05-20T01:15:53.209ZMay 20 01:15:53.120 DEBG [sc] ox: logging in
2332026-05-20T01:15:53.396ZMay 20 01:15:53.310 INFO ox: mounting /opt/cargo-bay
2342026-05-20T01:15:53.396ZMay 20 01:15:53.310 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2352026-05-20T01:15:54.179ZMay 20 01:15:54.084 DEBG [sc] cr2: logging in
2362026-05-20T01:15:54.556ZMay 20 01:15:54.533 INFO cr2: mounting /opt/cargo-bay
2372026-05-20T01:15:54.556ZMay 20 01:15:54.533 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2382026-05-20T01:15:54.593ZMay 20 01:15:54.555 DEBG [sc] cr2: executing command `cd`
2392026-05-20T01:15:54.593ZMay 20 01:15:54.566 INFO cr2: finished mounting /opt/cargo-bay
2402026-05-20T01:15:54.593ZMay 20 01:15:54.566 DEBG [sc] cr2: executing command `hostname cr2`
2412026-05-20T01:15:54.626ZMay 20 01:15:54.577 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
2422026-05-20T01:15:54.626ZMay 20 01:15:54.589 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
2432026-05-20T01:15:54.626ZMay 20 01:15:54.599 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
2442026-05-20T01:15:54.665ZMay 20 01:15:54.610 INFO cr2: logging out
2452026-05-20T01:15:54.754ZMay 20 01:15:54.737 DEBG [sc] ox: executing command `cd`
2462026-05-20T01:15:54.797ZMay 20 01:15:54.748 INFO ox: finished mounting /opt/cargo-bay
2472026-05-20T01:15:54.797ZMay 20 01:15:54.748 DEBG [sc] ox: executing command `hostname ox`
2482026-05-20T01:15:54.797ZMay 20 01:15:54.759 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
2492026-05-20T01:15:54.832ZMay 20 01:15:54.770 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
2502026-05-20T01:15:54.832ZMay 20 01:15:54.780 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
2512026-05-20T01:15:54.832ZMay 20 01:15:54.791 INFO ox: logging out
2522026-05-20T01:15:54.887ZMay 20 01:15:54.869 INFO ox: logged out
2532026-05-20T01:15:57.553ZMay 20 01:15:57.537 INFO cr2: logged out
2542026-05-20T01:15:57.586ZMay 20 01:15:57.537 DEBG [sc] ox: starting
2552026-05-20T01:15:57.586ZMay 20 01:15:57.537 DEBG [sc] ox: connecting to [::1]:59741
2562026-05-20T01:15:57.586ZMay 20 01:15:57.537 DEBG [sc] ox waiting for prompt
2572026-05-20T01:15:57.586ZMay 20 01:15:57.549 DEBG [sc] ox: logging in
2582026-05-20T01:15:57.656ZMay 20 01:15:57.637 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
2592026-05-20T01:16:03.429ZMay 20 01:16:03.406 DEBG [sc] ox: starting
2602026-05-20T01:16:03.429ZMay 20 01:16:03.406 DEBG [sc] ox: connecting to [::1]:59741
2612026-05-20T01:16:03.467ZMay 20 01:16:03.406 DEBG [sc] ox waiting for prompt
2622026-05-20T01:16:03.467ZMay 20 01:16:03.417 DEBG [sc] ox: logging in
2632026-05-20T01:16:03.523ZMay 20 01:16:03.504 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
2642026-05-20T01:16:03.615ZMay 20 01:16:03.593 DEBG [sc] ox: starting
2652026-05-20T01:16:03.615ZMay 20 01:16:03.593 DEBG [sc] ox: connecting to [::1]:59741
2662026-05-20T01:16:03.647ZMay 20 01:16:03.594 DEBG [sc] ox waiting for prompt
2672026-05-20T01:16:03.647ZMay 20 01:16:03.604 DEBG [sc] ox: logging in
2682026-05-20T01:16:03.712ZMay 20 01:16:03.693 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
2692026-05-20T01:16:03.775ZMay 20 01:16:03.758 INFO cr1: installing frr
2702026-05-20T01:16:03.775ZMay 20 01:16:03.758 INFO waiting for ceos to initialize
2712026-05-20T01:16:03.813ZMay 20 01:16:03.758 INFO ox: setting up npuvm
2722026-05-20T01:16:03.813ZMay 20 01:16:03.759 DEBG [sc] cr1: starting
2732026-05-20T01:16:03.813ZMay 20 01:16:03.759 DEBG [sc] cr1: connecting to [::1]:50879
2742026-05-20T01:16:03.813ZMay 20 01:16:03.759 DEBG [sc] cr2: starting
2752026-05-20T01:16:03.813ZMay 20 01:16:03.759 DEBG [sc] ox: starting
2762026-05-20T01:16:03.813ZMay 20 01:16:03.759 DEBG [sc] cr2: connecting to [::1]:54330
2772026-05-20T01:16:03.813ZMay 20 01:16:03.759 DEBG [sc] ox: connecting to [::1]:59741
2782026-05-20T01:16:03.813ZMay 20 01:16:03.759 DEBG [sc] ox waiting for prompt
2792026-05-20T01:16:03.813ZMay 20 01:16:03.759 DEBG [sc] cr2 waiting for prompt
2802026-05-20T01:16:03.813ZMay 20 01:16:03.759 DEBG [sc] cr1 waiting for prompt
2812026-05-20T01:16:03.813ZMay 20 01:16:03.770 DEBG [sc] ox: logging in
2822026-05-20T01:16:03.813ZMay 20 01:16:03.771 DEBG [sc] cr1: logging in
2832026-05-20T01:16:03.813ZMay 20 01:16:03.771 DEBG [sc] cr2: logging in
2842026-05-20T01:16:03.876ZMay 20 01:16:03.857 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
2852026-05-20T01:16:03.930ZMay 20 01:16:03.914 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
2862026-05-20T01:16:04.140ZMay 20 01:16:04.120 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
2872026-05-20T01:16:06.158ZMay 20 01:16:06.135 INFO cr2: executing eos script show version
2882026-05-20T01:16:06.158ZMay 20 01:16:06.135 DEBG [sc] cr2: starting
2892026-05-20T01:16:06.158ZMay 20 01:16:06.135 DEBG [sc] cr2: connecting to [::1]:54330
2902026-05-20T01:16:06.199ZMay 20 01:16:06.135 DEBG [sc] cr2 waiting for prompt
2912026-05-20T01:16:06.199ZMay 20 01:16:06.145 DEBG [sc] cr2: logging in
2922026-05-20T01:16:06.327ZMay 20 01:16:06.300 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
2932026-05-20T01:16:12.208ZMay 20 01:16:12.189 DEBG [sc] ox: starting
2942026-05-20T01:16:12.208ZMay 20 01:16:12.189 DEBG [sc] ox: connecting to [::1]:59741
2952026-05-20T01:16:12.245ZMay 20 01:16:12.189 DEBG [sc] ox waiting for prompt
2962026-05-20T01:16:12.245ZMay 20 01:16:12.200 DEBG [sc] ox: logging in
2972026-05-20T01:16:12.298ZMay 20 01:16:12.277 DEBG [sc] ox: executing command `chmod +x npuvm`
2982026-05-20T01:16:12.365ZMay 20 01:16:12.344 DEBG [sc] ox: starting
2992026-05-20T01:16:12.365ZMay 20 01:16:12.344 DEBG [sc] ox: connecting to [::1]:59741
3002026-05-20T01:16:12.400ZMay 20 01:16:12.345 DEBG [sc] ox waiting for prompt
3012026-05-20T01:16:12.400ZMay 20 01:16:12.355 DEBG [sc] ox: logging in
3022026-05-20T01:16:12.453ZMay 20 01:16:12.432 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
3032026-05-20T01:16:14.519ZMay 20 01:16:14.495 DEBG [sc] cr2: starting
3042026-05-20T01:16:14.519ZMay 20 01:16:14.495 DEBG [sc] cr2: connecting to [::1]:54330
3052026-05-20T01:16:14.560ZMay 20 01:16:14.496 DEBG [sc] cr2 waiting for prompt
3062026-05-20T01:16:14.560ZMay 20 01:16:14.507 DEBG [sc] cr2: logging in
3072026-05-20T01:16:14.672ZMay 20 01:16:14.649 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3082026-05-20T01:16:16.795ZMay 20 01:16:16.772 INFO cr2: executing eos script show version
3092026-05-20T01:16:16.795ZMay 20 01:16:16.772 DEBG [sc] cr2: starting
3102026-05-20T01:16:16.795ZMay 20 01:16:16.772 DEBG [sc] cr2: connecting to [::1]:54330
3112026-05-20T01:16:16.833ZMay 20 01:16:16.773 DEBG [sc] cr2 waiting for prompt
3122026-05-20T01:16:16.833ZMay 20 01:16:16.783 DEBG [sc] cr2: logging in
3132026-05-20T01:16:16.950ZMay 20 01:16:16.927 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3142026-05-20T01:16:19.359ZMay 20 01:16:19.303 INFO cr2: executing eos script
3152026-05-20T01:16:19.360Z enable
3162026-05-20T01:16:19.360Z configure
3172026-05-20T01:16:19.360Z ipv6 unicast-routing
3182026-05-20T01:16:19.360Z ip routing ipv6 interfaces
3192026-05-20T01:16:19.360Z ip routing
3202026-05-20T01:16:19.360Z ip route 1.2.3.0/24 null0
3212026-05-20T01:16:19.360Z ipv6 route fd99::/64 null0
3222026-05-20T01:16:19.360Z interface et1
3232026-05-20T01:16:19.360Z no switchport
3242026-05-20T01:16:19.360Z ipv6 enable
3252026-05-20T01:16:19.360Z
3262026-05-20T01:16:19.360Z router bgp 45
3272026-05-20T01:16:19.360Z router-id 1.2.3.1
3282026-05-20T01:16:19.360Z no bgp default ipv4-unicast
3292026-05-20T01:16:19.360Z timers bgp 2 6
3302026-05-20T01:16:19.360Z neighbor ebgp peer group
3312026-05-20T01:16:19.360Z neighbor ebgp remote-as 33
3322026-05-20T01:16:19.360Z neighbor interface Et1 peer-group ebgp
3332026-05-20T01:16:19.360Z address-family ipv4
3342026-05-20T01:16:19.360Z neighbor ebgp activate
3352026-05-20T01:16:19.360Z neighbor ebgp next-hop address-family ipv6 originate
3362026-05-20T01:16:19.360Z network 1.2.3.0/24
3372026-05-20T01:16:19.360Z exit
3382026-05-20T01:16:19.360Z address-family ipv6
3392026-05-20T01:16:19.360Z neighbor ebgp activate
3402026-05-20T01:16:19.360Z neighbor ebgp next-hop address-family ipv6 originate
3412026-05-20T01:16:19.360Z network fd99::/64
3422026-05-20T01:16:19.360Z exit
3432026-05-20T01:16:19.360Z exit
3442026-05-20T01:16:19.360Z
3452026-05-20T01:16:19.360ZMay 20 01:16:19.303 DEBG [sc] cr2: starting
3462026-05-20T01:16:19.360ZMay 20 01:16:19.303 DEBG [sc] cr2: connecting to [::1]:54330
3472026-05-20T01:16:19.435ZMay 20 01:16:19.304 DEBG [sc] cr2 waiting for prompt
3482026-05-20T01:16:19.435ZMay 20 01:16:19.314 DEBG [sc] cr2: logging in
3492026-05-20T01:16:19.469ZMay 20 01:16:19.446 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
3502026-05-20T01:16:19.469Z enable
3512026-05-20T01:16:19.469Z configure
3522026-05-20T01:16:19.469Z ipv6 unicast-routing
3532026-05-20T01:16:19.469Z ip routing ipv6 interfaces
3542026-05-20T01:16:19.469Z ip routing
3552026-05-20T01:16:19.469Z ip route 1.2.3.0/24 null0
3562026-05-20T01:16:19.469Z ipv6 route fd99::/64 null0
3572026-05-20T01:16:19.469Z interface et1
3582026-05-20T01:16:19.469Z no switchport
3592026-05-20T01:16:19.470Z ipv6 enable
3602026-05-20T01:16:19.470Z
3612026-05-20T01:16:19.470Z router bgp 45
3622026-05-20T01:16:19.470Z router-id 1.2.3.1
3632026-05-20T01:16:19.470Z no bgp default ipv4-unicast
3642026-05-20T01:16:19.470Z timers bgp 2 6
3652026-05-20T01:16:19.470Z neighbor ebgp peer group
3662026-05-20T01:16:19.470Z neighbor ebgp remote-as 33
3672026-05-20T01:16:19.470Z neighbor interface Et1 peer-group ebgp
3682026-05-20T01:16:19.470Z address-family ipv4
3692026-05-20T01:16:19.470Z neighbor ebgp activate
3702026-05-20T01:16:19.470Z neighbor ebgp next-hop address-family ipv6 originate
3712026-05-20T01:16:19.470Z network 1.2.3.0/24
3722026-05-20T01:16:19.470Z exit
3732026-05-20T01:16:19.470Z address-family ipv6
3742026-05-20T01:16:19.470Z neighbor ebgp activate
3752026-05-20T01:16:19.470Z neighbor ebgp next-hop address-family ipv6 originate
3762026-05-20T01:16:19.470Z network fd99::/64
3772026-05-20T01:16:19.470Z exit
3782026-05-20T01:16:19.470Z exit
3792026-05-20T01:16:19.470Z '`
3802026-05-20T01:16:41.782ZMay 20 01:16:41.754 INFO cr1: enabling frr daemon bgpd
3812026-05-20T01:16:41.782ZMay 20 01:16:41.754 DEBG [sc] cr1: starting
3822026-05-20T01:16:41.782ZMay 20 01:16:41.754 DEBG [sc] cr1: connecting to [::1]:50879
3832026-05-20T01:16:41.817ZMay 20 01:16:41.755 DEBG [sc] cr1 waiting for prompt
3842026-05-20T01:16:41.817ZMay 20 01:16:41.765 DEBG [sc] cr1: logging in
3852026-05-20T01:16:41.924ZMay 20 01:16:41.897 DEBG [sc] cr1: executing command `sed -i 's/bgpd=no/bgpd=yes/g' /etc/frr/daemons`
3862026-05-20T01:16:43.992ZMay 20 01:16:43.971 DEBG [sc] cr1: starting
3872026-05-20T01:16:43.992ZMay 20 01:16:43.971 DEBG [sc] cr1: connecting to [::1]:50879
3882026-05-20T01:16:44.028ZMay 20 01:16:43.971 DEBG [sc] cr1 waiting for prompt
3892026-05-20T01:16:44.028ZMay 20 01:16:43.982 DEBG [sc] cr1: logging in
3902026-05-20T01:16:44.135ZMay 20 01:16:44.114 DEBG [sc] cr1: executing command `systemctl restart frr`
3912026-05-20T01:16:51.831ZMay 20 01:16:51.727 INFO cr1: executing frr script
3922026-05-20T01:16:51.831Z configure
3932026-05-20T01:16:51.831Z ip forwarding
3942026-05-20T01:16:51.831Z ipv6 forwarding
3952026-05-20T01:16:51.831Z ip route 1.2.3.0/24 null0
3962026-05-20T01:16:51.831Z ipv6 route fd99::/64 null0
3972026-05-20T01:16:51.831Z router bgp 44
3982026-05-20T01:16:51.831Z no bgp ebgp-requires-policy
3992026-05-20T01:16:51.831Z timers bgp 2 6
4002026-05-20T01:16:51.831Z neighbor enp0s8 interface remote-as external
4012026-05-20T01:16:51.831Z neighbor enp0s8 timers connect 1
4022026-05-20T01:16:51.831Z address-family ipv4 unicast
4032026-05-20T01:16:51.831Z network 1.2.3.0/24
4042026-05-20T01:16:51.831Z neighbor enp0s8 activate
4052026-05-20T01:16:51.831Z exit-address-family
4062026-05-20T01:16:51.831Z address-family ipv6 unicast
4072026-05-20T01:16:51.831Z network fd99::/64
4082026-05-20T01:16:51.831Z neighbor enp0s8 activate
4092026-05-20T01:16:51.831Z exit-address-family
4102026-05-20T01:16:51.831Z exit
4112026-05-20T01:16:51.831Z
4122026-05-20T01:16:51.956ZMay 20 01:16:51.728 DEBG [sc] cr1: starting
4132026-05-20T01:16:51.957ZMay 20 01:16:51.728 DEBG [sc] cr1: connecting to [::1]:50879
4142026-05-20T01:16:51.957ZMay 20 01:16:51.728 DEBG [sc] cr1 waiting for prompt
4152026-05-20T01:16:51.957ZMay 20 01:16:51.739 DEBG [sc] cr1: logging in
4162026-05-20T01:16:52.094ZMay 20 01:16:51.872 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-20T01:18:47.434ZMay 20 01:18:47.406 DEBG [sc] ox: starting
4182026-05-20T01:18:47.434ZMay 20 01:18:47.406 DEBG [sc] ox: connecting to [::1]:59741
4192026-05-20T01:18:47.531ZMay 20 01:18:47.407 DEBG [sc] ox waiting for prompt
4202026-05-20T01:18:47.531ZMay 20 01:18:47.417 DEBG [sc] ox: logging in
4212026-05-20T01:18:47.723ZMay 20 01:18:47.494 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
4222026-05-20T01:18:48.503ZMay 20 01:18:47.763 DEBG [sc] ox: starting
4232026-05-20T01:18:48.503ZMay 20 01:18:47.763 DEBG [sc] ox: connecting to [::1]:59741
4242026-05-20T01:18:49.481ZMay 20 01:18:47.763 DEBG [sc] ox waiting for prompt
4252026-05-20T01:18:49.481ZMay 20 01:18:47.775 DEBG [sc] ox: logging in
4262026-05-20T01:18:49.481ZMay 20 01:18:47.853 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4272026-05-20T01:18:51.124ZMay 20 01:18:48.876 DEBG [sc] ox: starting
4282026-05-20T01:18:51.124ZMay 20 01:18:48.876 DEBG [sc] ox: connecting to [::1]:59741
4292026-05-20T01:18:51.124ZMay 20 01:18:48.877 DEBG [sc] ox waiting for prompt
4302026-05-20T01:18:51.124ZMay 20 01:18:48.877 DEBG [sc] ox: logging in
4312026-05-20T01:18:51.124ZMay 20 01:18:48.953 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4322026-05-20T01:18:51.124ZMay 20 01:18:49.009 DEBG [sc] ox: starting
4332026-05-20T01:18:51.124ZMay 20 01:18:49.009 DEBG [sc] ox: connecting to [::1]:59741
4342026-05-20T01:18:51.124ZMay 20 01:18:49.010 DEBG [sc] ox waiting for prompt
4352026-05-20T01:18:51.124ZMay 20 01:18:49.019 DEBG [sc] ox: logging in
4362026-05-20T01:18:51.124ZMay 20 01:18:49.097 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
4372026-05-20T01:18:51.124ZMay 20 01:18:49.152 DEBG [sc] ox: starting
4382026-05-20T01:18:51.124ZMay 20 01:18:49.152 DEBG [sc] ox: connecting to [::1]:59741
4392026-05-20T01:18:51.124ZMay 20 01:18:49.153 DEBG [sc] ox waiting for prompt
4402026-05-20T01:18:51.124ZMay 20 01:18:49.163 DEBG [sc] ox: logging in
4412026-05-20T01:18:51.124ZMay 20 01:18:49.240 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
4422026-05-20T01:18:51.124ZMay 20 01:18:49.295 DEBG [sc] ox: starting
4432026-05-20T01:18:51.124ZMay 20 01:18:49.295 DEBG [sc] ox: connecting to [::1]:59741
4442026-05-20T01:18:51.124ZMay 20 01:18:49.296 DEBG [sc] ox waiting for prompt
4452026-05-20T01:18:51.125ZMay 20 01:18:49.306 DEBG [sc] ox: logging in
4462026-05-20T01:18:52.321ZMay 20 01:18:49.384 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
4472026-05-20T01:18:52.321ZMay 20 01:18:49.439 DEBG [sc] ox: starting
4482026-05-20T01:18:52.321ZMay 20 01:18:49.439 DEBG [sc] ox: connecting to [::1]:59741
4492026-05-20T01:18:52.321ZMay 20 01:18:49.440 DEBG [sc] ox waiting for prompt
4502026-05-20T01:18:52.321ZMay 20 01:18:49.450 DEBG [sc] ox: logging in
4512026-05-20T01:18:52.321ZMay 20 01:18:49.526 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
4522026-05-20T01:18:52.321ZMay 20 01:18:49.582 DEBG [sc] ox: starting
4532026-05-20T01:18:52.321ZMay 20 01:18:49.582 DEBG [sc] ox: connecting to [::1]:59741
4542026-05-20T01:18:52.322ZMay 20 01:18:49.583 DEBG [sc] ox waiting for prompt
4552026-05-20T01:18:52.322ZMay 20 01:18:49.593 DEBG [sc] ox: logging in
4562026-05-20T01:18:52.322ZMay 20 01:18:49.670 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
4572026-05-20T01:18:52.322ZMay 20 01:18:49.726 DEBG [sc] ox: starting
4582026-05-20T01:18:52.322ZMay 20 01:18:49.726 DEBG [sc] ox: connecting to [::1]:59741
4592026-05-20T01:18:52.322ZMay 20 01:18:49.727 DEBG [sc] ox waiting for prompt
4602026-05-20T01:18:52.322ZMay 20 01:18:49.737 DEBG [sc] ox: logging in
4612026-05-20T01:18:52.322ZMay 20 01:18:49.814 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
4622026-05-20T01:18:52.322ZMay 20 01:18:49.869 DEBG [sc] ox: starting
4632026-05-20T01:18:52.322ZMay 20 01:18:49.869 DEBG [sc] ox: connecting to [::1]:59741
4642026-05-20T01:18:52.322ZMay 20 01:18:49.869 DEBG [sc] ox waiting for prompt
4652026-05-20T01:18:52.322ZMay 20 01:18:49.880 DEBG [sc] ox: logging in
4662026-05-20T01:18:52.322ZMay 20 01:18:49.958 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
4672026-05-20T01:18:52.322ZMay 20 01:18:50.029 INFO adding BGP router to mgd
4682026-05-20T01:18:53.352ZMay 20 01:18:53.132 INFO cr1: executing frr script show ip bgp json
4692026-05-20T01:18:53.352ZMay 20 01:18:53.132 DEBG [sc] cr1: starting
4702026-05-20T01:18:53.352ZMay 20 01:18:53.132 DEBG [sc] cr1: connecting to [::1]:50879
4712026-05-20T01:18:53.441ZMay 20 01:18:53.133 DEBG [sc] cr1 waiting for prompt
4722026-05-20T01:18:53.441ZMay 20 01:18:53.144 DEBG [sc] cr1: logging in
4732026-05-20T01:18:53.506ZMay 20 01:18:53.485 DEBG [sc] cr1: executing command `vtysh -c 'show ip bgp json'`
4742026-05-20T01:18:55.793ZMay 20 01:18:55.615 INFO cr1: executing frr script show bgp json
4752026-05-20T01:18:55.793ZMay 20 01:18:55.615 DEBG [sc] cr1: starting
4762026-05-20T01:18:55.793ZMay 20 01:18:55.615 DEBG [sc] cr1: connecting to [::1]:50879
4772026-05-20T01:18:55.870ZMay 20 01:18:55.616 DEBG [sc] cr1 waiting for prompt
4782026-05-20T01:18:55.870ZMay 20 01:18:55.627 DEBG [sc] cr1: logging in
4792026-05-20T01:18:55.870ZMay 20 01:18:55.759 DEBG [sc] cr1: executing command `vtysh -c 'show bgp json'`
4802026-05-20T01:18:57.909ZMay 20 01:18:57.892 INFO cr2: executing eos script show ip bgp | json
4812026-05-20T01:18:57.909ZMay 20 01:18:57.892 DEBG [sc] cr2: starting
4822026-05-20T01:18:57.942ZMay 20 01:18:57.892 DEBG [sc] cr2: connecting to [::1]:54330
4832026-05-20T01:18:57.942ZMay 20 01:18:57.893 DEBG [sc] cr2 waiting for prompt
4842026-05-20T01:18:57.942ZMay 20 01:18:57.903 DEBG [sc] cr2: logging in
4852026-05-20T01:18:58.272ZMay 20 01:18:58.255 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ip bgp | json'`
4862026-05-20T01:19:00.625ZMay 20 01:19:00.607 INFO cr2: executing eos script show ipv6 bgp | json
4872026-05-20T01:19:00.625ZMay 20 01:19:00.607 DEBG [sc] cr2: starting
4882026-05-20T01:19:00.625ZMay 20 01:19:00.607 DEBG [sc] cr2: connecting to [::1]:54330
4892026-05-20T01:19:00.659ZMay 20 01:19:00.608 DEBG [sc] cr2 waiting for prompt
4902026-05-20T01:19:00.659ZMay 20 01:19:00.618 DEBG [sc] cr2: logging in
4912026-05-20T01:19:00.759ZMay 20 01:19:00.740 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ipv6 bgp | json'`
4922026-05-20T01:19:03.134ZMay 20 01:19:03.114 INFO trio bgp unnumbered test passed 🎉
4932026-05-20T01:19:03.134ZMay 20 01:19:03.115 INFO destroying runner for deployment mgtriou
4942026-05-20T01:19:03.134ZMay 20 01:19:03.115 INFO destroying deployment mgtriou
4952026-05-20T01:19:03.134ZMay 20 01:19:03.115 INFO destroying nodes
4962026-05-20T01:19:03.244ZMay 20 01:19:03.220 INFO destroying links
4972026-05-20T01:19:03.244ZMay 20 01:19:03.220 INFO destroying link mgtriou_ox_sn_vnic0
4982026-05-20T01:19:03.278ZMay 20 01:19:03.222 INFO destroying link mgtriou_ox_sn_sim0
4992026-05-20T01:19:03.278ZMay 20 01:19:03.224 INFO destroying link mgtriou_cr1_vn_vnic0
5002026-05-20T01:19:04.250ZMay 20 01:19:04.227 INFO destroying link mgtriou_cr1_vn_sim0
5012026-05-20T01:19:04.283ZMay 20 01:19:04.229 INFO destroying link mgtriou_ox_sn_vnic1
5022026-05-20T01:19:04.283ZMay 20 01:19:04.230 INFO destroying link mgtriou_ox_sn_sim1
5032026-05-20T01:19:04.283ZMay 20 01:19:04.231 INFO destroying link mgtriou_cr2_vn_vnic0
5042026-05-20T01:19:04.283ZMay 20 01:19:04.233 INFO destroying link mgtriou_cr2_vn_sim0
5052026-05-20T01:19:04.283ZMay 20 01:19:04.234 INFO destroying external links
5062026-05-20T01:19:04.283ZMay 20 01:19:04.234 INFO destroying external link mgtriou_ox_vn_vnic2
5072026-05-20T01:19:04.283ZMay 20 01:19:04.235 INFO destroying external link mgtriou_cr1_vn_vnic1
5082026-05-20T01:19:04.283ZMay 20 01:19:04.236 INFO destroying external link mgtriou_cr2_vn_vnic1
5092026-05-20T01:19:04.283ZMay 20 01:19:04.238 INFO destroying images
5102026-05-20T01:19:04.740ZMay 20 01:19:04.724 INFO destroying workspace at .falcon
5112026-05-20T01:19:04.774Z+ RUST_LOG=debug
5122026-05-20T01:19:04.774Z+ pfexec ./falcon-lab run trio-bfd-static-routing
5132026-05-20T01:19:04.805ZMay 20 01:19:04.767 DEBG using default route interface igb0
5142026-05-20T01:19:04.805ZMay 20 01:19:04.767 DEBG using default route interface igb0
5152026-05-20T01:19:04.805ZMay 20 01:19:04.767 DEBG using default route interface igb0
5162026-05-20T01:19:04.805ZMay 20 01:19:04.767 INFO launching runner: deployment(mgtriobfd) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
5172026-05-20T01:19:04.805ZMay 20 01:19:04.767 INFO starting preflight for deployment mgtriobfd
5182026-05-20T01:19:20.065ZMay 20 01:19:20.040 WARN error sending request for url (https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/OVMF_CODE.fd.sha256.txt): retrying in 1 second
5192026-05-20T01:19:36.065ZMay 20 01:19:36.043 WARN error sending request for url (https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/OVMF_CODE.fd.sha256.txt): retrying in 1 second
5202026-05-20T01:19:37.585ZMay 20 01:19:37.557 INFO creating links
5212026-05-20T01:19:37.585ZMay 20 01:19:37.557 DEBG destroying link mgtriobfd_ox_sn_vnic0
5222026-05-20T01:19:37.586ZMay 20 01:19:37.557 DEBG destroying link mgtriobfd_ox_sn_sim0
5232026-05-20T01:19:37.586ZMay 20 01:19:37.557 INFO creating simnet link 'mgtriobfd_ox_sn_sim0'
5242026-05-20T01:19:37.649ZMay 20 01:19:37.560 INFO creating vnic link 'mgtriobfd_ox_sn_vnic0'
5252026-05-20T01:19:37.649ZMay 20 01:19:37.567 DEBG link pair created
5262026-05-20T01:19:37.649ZMay 20 01:19:37.567 DEBG destroying link mgtriobfd_cr1_vn_vnic0
5272026-05-20T01:19:37.649ZMay 20 01:19:37.567 DEBG destroying link mgtriobfd_cr1_vn_sim0
5282026-05-20T01:19:37.649ZMay 20 01:19:37.567 INFO creating simnet link 'mgtriobfd_cr1_vn_sim0'
5292026-05-20T01:19:37.649ZMay 20 01:19:37.568 INFO creating vnic link 'mgtriobfd_cr1_vn_vnic0'
5302026-05-20T01:19:37.649ZMay 20 01:19:37.575 DEBG link pair created
5312026-05-20T01:19:37.649ZMay 20 01:19:37.575 DEBG destroying link mgtriobfd_ox_sn_vnic1
5322026-05-20T01:19:37.649ZMay 20 01:19:37.575 DEBG destroying link mgtriobfd_ox_sn_sim1
5332026-05-20T01:19:37.649ZMay 20 01:19:37.575 INFO creating simnet link 'mgtriobfd_ox_sn_sim1'
5342026-05-20T01:19:37.649ZMay 20 01:19:37.576 INFO creating vnic link 'mgtriobfd_ox_sn_vnic1'
5352026-05-20T01:19:37.649ZMay 20 01:19:37.583 DEBG link pair created
5362026-05-20T01:19:37.650ZMay 20 01:19:37.583 DEBG destroying link mgtriobfd_cr2_vn_vnic0
5372026-05-20T01:19:37.650ZMay 20 01:19:37.583 DEBG destroying link mgtriobfd_cr2_vn_sim0
5382026-05-20T01:19:37.650ZMay 20 01:19:37.583 INFO creating simnet link 'mgtriobfd_cr2_vn_sim0'
5392026-05-20T01:19:37.650ZMay 20 01:19:37.584 INFO creating vnic link 'mgtriobfd_cr2_vn_vnic0'
5402026-05-20T01:19:37.650ZMay 20 01:19:37.591 DEBG link pair created
5412026-05-20T01:19:37.650ZMay 20 01:19:37.591 INFO creating external links
5422026-05-20T01:19:37.650ZMay 20 01:19:37.591 DEBG destroying external link mgtriobfd_ox_vn_vnic2
5432026-05-20T01:19:37.650ZMay 20 01:19:37.591 INFO creating external link mgtriobfd_ox_vn_vnic2
5442026-05-20T01:19:37.650ZMay 20 01:19:37.593 DEBG external link mgtriobfd_ox_vn_vnic2@igb0 created
5452026-05-20T01:19:37.650ZMay 20 01:19:37.593 DEBG destroying external link mgtriobfd_cr1_vn_vnic1
5462026-05-20T01:19:37.650ZMay 20 01:19:37.593 INFO creating external link mgtriobfd_cr1_vn_vnic1
5472026-05-20T01:19:37.650ZMay 20 01:19:37.594 DEBG external link mgtriobfd_cr1_vn_vnic1@igb0 created
5482026-05-20T01:19:37.650ZMay 20 01:19:37.594 DEBG destroying external link mgtriobfd_cr2_vn_vnic1
5492026-05-20T01:19:37.650ZMay 20 01:19:37.594 INFO creating external link mgtriobfd_cr2_vn_vnic1
5502026-05-20T01:19:37.650ZMay 20 01:19:37.595 DEBG external link mgtriobfd_cr2_vn_vnic1@igb0 created
5512026-05-20T01:19:37.650ZMay 20 01:19:37.595 INFO creating nodes
5522026-05-20T01:19:37.650ZMay 20 01:19:37.595 INFO ox: launching node
5532026-05-20T01:19:37.650ZMay 20 01:19:37.597 INFO cr1: launching node
5542026-05-20T01:19:37.650ZMay 20 01:19:37.599 INFO cr2: launching node
5552026-05-20T01:19:37.683ZMay 20 01:19:37.613 INFO launched instance ox with pid 888 on port 64677
5562026-05-20T01:19:37.683ZMay 20 01:19:37.613 INFO ox: instance ensure
5572026-05-20T01:19:37.683ZMay 20 01:19:37.613 INFO launched instance cr1 with pid 889 on port 55766
5582026-05-20T01:19:37.683ZMay 20 01:19:37.613 INFO cr1: instance ensure
5592026-05-20T01:19:37.683ZMay 20 01:19:37.614 INFO launched instance cr2 with pid 890 on port 56559
5602026-05-20T01:19:37.683ZMay 20 01:19:37.614 INFO cr2: instance ensure
5612026-05-20T01:19:39.941ZMay 20 01:19:39.916 INFO ox: instance ensure completed after 0 retries
5622026-05-20T01:19:39.941ZMay 20 01:19:39.916 INFO ox: instance run
5632026-05-20T01:19:39.975ZMay 20 01:19:39.917 DEBG [sc] ox: starting
5642026-05-20T01:19:39.975ZMay 20 01:19:39.917 DEBG [sc] ox: connecting to [::1]:64677
5652026-05-20T01:19:39.975ZMay 20 01:19:39.918 DEBG [sc] ox waiting for prompt
5662026-05-20T01:19:39.975ZMay 20 01:19:39.948 INFO cr1: instance ensure completed after 0 retries
5672026-05-20T01:19:39.975ZMay 20 01:19:39.948 INFO cr1: instance run
5682026-05-20T01:19:39.975ZMay 20 01:19:39.948 DEBG [sc] cr1: starting
5692026-05-20T01:19:39.975ZMay 20 01:19:39.948 DEBG [sc] cr1: connecting to [::1]:55766
5702026-05-20T01:19:39.975ZMay 20 01:19:39.949 DEBG [sc] cr1 waiting for prompt
5712026-05-20T01:19:40.043ZMay 20 01:19:40.025 INFO cr2: instance ensure completed after 0 retries
5722026-05-20T01:19:40.043ZMay 20 01:19:40.025 INFO cr2: instance run
5732026-05-20T01:19:40.075ZMay 20 01:19:40.026 DEBG [sc] cr2: starting
5742026-05-20T01:19:40.075ZMay 20 01:19:40.026 DEBG [sc] cr2: connecting to [::1]:56559
5752026-05-20T01:19:40.075ZMay 20 01:19:40.026 DEBG [sc] cr2 waiting for prompt
5762026-05-20T01:19:56.984ZMay 20 01:19:56.966 DEBG [sc] cr1: logging in
5772026-05-20T01:19:57.395ZMay 20 01:19:57.376 INFO cr1: mounting /opt/cargo-bay
5782026-05-20T01:19:57.395ZMay 20 01:19:57.376 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5792026-05-20T01:19:57.427ZMay 20 01:19:57.397 DEBG [sc] cr1: executing command `cd`
5802026-05-20T01:19:57.427ZMay 20 01:19:57.408 INFO cr1: finished mounting /opt/cargo-bay
5812026-05-20T01:19:57.427ZMay 20 01:19:57.408 DEBG [sc] cr1: executing command `hostname cr1`
5822026-05-20T01:19:57.462ZMay 20 01:19:57.420 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
5832026-05-20T01:19:57.462ZMay 20 01:19:57.431 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
5842026-05-20T01:19:57.506ZMay 20 01:19:57.442 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
5852026-05-20T01:19:57.506ZMay 20 01:19:57.453 INFO cr1: logging out
5862026-05-20T01:19:58.165ZMay 20 01:19:58.148 DEBG [sc] ox: logging in
5872026-05-20T01:19:58.321ZMay 20 01:19:58.302 INFO ox: mounting /opt/cargo-bay
5882026-05-20T01:19:58.321ZMay 20 01:19:58.302 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5892026-05-20T01:19:59.534ZMay 20 01:19:59.512 INFO cr1: logged out
5902026-05-20T01:19:59.567ZMay 20 01:19:59.519 DEBG [sc] ox: executing command `cd`
5912026-05-20T01:19:59.567ZMay 20 01:19:59.531 INFO ox: finished mounting /opt/cargo-bay
5922026-05-20T01:19:59.567ZMay 20 01:19:59.531 DEBG [sc] ox: executing command `hostname ox`
5932026-05-20T01:19:59.567ZMay 20 01:19:59.542 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
5942026-05-20T01:19:59.607ZMay 20 01:19:59.553 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
5952026-05-20T01:19:59.607ZMay 20 01:19:59.564 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
5962026-05-20T01:19:59.607ZMay 20 01:19:59.575 INFO ox: logging out
5972026-05-20T01:19:59.671ZMay 20 01:19:59.652 INFO ox: logged out
5982026-05-20T01:20:01.643ZMay 20 01:20:01.625 DEBG [sc] cr2: logging in
5992026-05-20T01:20:02.030ZMay 20 01:20:02.010 INFO cr2: mounting /opt/cargo-bay
6002026-05-20T01:20:02.031ZMay 20 01:20:02.010 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
6012026-05-20T01:20:02.068ZMay 20 01:20:02.021 DEBG [sc] cr2: executing command `cd`
6022026-05-20T01:20:02.068ZMay 20 01:20:02.032 INFO cr2: finished mounting /opt/cargo-bay
6032026-05-20T01:20:02.068ZMay 20 01:20:02.032 DEBG [sc] cr2: executing command `hostname cr2`
6042026-05-20T01:20:02.068ZMay 20 01:20:02.043 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
6052026-05-20T01:20:02.105ZMay 20 01:20:02.054 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
6062026-05-20T01:20:02.105ZMay 20 01:20:02.065 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
6072026-05-20T01:20:02.105ZMay 20 01:20:02.076 INFO cr2: logging out
6082026-05-20T01:20:05.064ZMay 20 01:20:05.047 INFO cr2: logged out
6092026-05-20T01:20:05.098ZMay 20 01:20:05.047 DEBG [sc] ox: starting
6102026-05-20T01:20:05.098ZMay 20 01:20:05.047 DEBG [sc] ox: connecting to [::1]:64677
6112026-05-20T01:20:05.098ZMay 20 01:20:05.048 DEBG [sc] ox waiting for prompt
6122026-05-20T01:20:05.098ZMay 20 01:20:05.059 DEBG [sc] ox: logging in
6132026-05-20T01:20:05.167ZMay 20 01:20:05.147 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
6142026-05-20T01:20:09.767ZMay 20 01:20:09.745 DEBG [sc] ox: starting
6152026-05-20T01:20:09.767ZMay 20 01:20:09.745 DEBG [sc] ox: connecting to [::1]:64677
6162026-05-20T01:20:09.799ZMay 20 01:20:09.746 DEBG [sc] ox waiting for prompt
6172026-05-20T01:20:09.799ZMay 20 01:20:09.756 DEBG [sc] ox: logging in
6182026-05-20T01:20:09.861ZMay 20 01:20:09.843 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
6192026-05-20T01:20:09.953ZMay 20 01:20:09.932 DEBG [sc] ox: starting
6202026-05-20T01:20:09.953ZMay 20 01:20:09.932 DEBG [sc] ox: connecting to [::1]:64677
6212026-05-20T01:20:09.993ZMay 20 01:20:09.932 DEBG [sc] ox waiting for prompt
6222026-05-20T01:20:09.994ZMay 20 01:20:09.943 DEBG [sc] ox: logging in
6232026-05-20T01:20:10.048ZMay 20 01:20:10.031 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
6242026-05-20T01:20:10.118ZMay 20 01:20:10.097 INFO cr1: installing frr
6252026-05-20T01:20:10.118ZMay 20 01:20:10.097 INFO waiting for ceos to initialize
6262026-05-20T01:20:10.118ZMay 20 01:20:10.097 INFO ox: setting up npuvm
6272026-05-20T01:20:10.150ZMay 20 01:20:10.097 DEBG [sc] ox: starting
6282026-05-20T01:20:10.150ZMay 20 01:20:10.097 DEBG [sc] ox: connecting to [::1]:64677
6292026-05-20T01:20:10.150ZMay 20 01:20:10.097 DEBG [sc] cr1: starting
6302026-05-20T01:20:10.150ZMay 20 01:20:10.097 DEBG [sc] cr2: starting
6312026-05-20T01:20:10.151ZMay 20 01:20:10.097 DEBG [sc] cr1: connecting to [::1]:55766
6322026-05-20T01:20:10.151ZMay 20 01:20:10.097 DEBG [sc] cr2: connecting to [::1]:56559
6332026-05-20T01:20:10.151ZMay 20 01:20:10.098 DEBG [sc] ox waiting for prompt
6342026-05-20T01:20:10.151ZMay 20 01:20:10.098 DEBG [sc] cr1 waiting for prompt
6352026-05-20T01:20:10.151ZMay 20 01:20:10.098 DEBG [sc] cr2 waiting for prompt
6362026-05-20T01:20:10.151ZMay 20 01:20:10.107 DEBG [sc] ox: logging in
6372026-05-20T01:20:10.151ZMay 20 01:20:10.109 DEBG [sc] cr2: logging in
6382026-05-20T01:20:10.151ZMay 20 01:20:10.109 DEBG [sc] cr1: logging in
6392026-05-20T01:20:10.203ZMay 20 01:20:10.184 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
6402026-05-20T01:20:10.265ZMay 20 01:20:10.243 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6412026-05-20T01:20:10.501ZMay 20 01:20:10.485 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
6422026-05-20T01:20:12.532ZMay 20 01:20:12.515 INFO cr2: executing eos script show version
6432026-05-20T01:20:12.532ZMay 20 01:20:12.515 DEBG [sc] cr2: starting
6442026-05-20T01:20:12.532ZMay 20 01:20:12.515 DEBG [sc] cr2: connecting to [::1]:56559
6452026-05-20T01:20:12.562ZMay 20 01:20:12.516 DEBG [sc] cr2 waiting for prompt
6462026-05-20T01:20:12.562ZMay 20 01:20:12.526 DEBG [sc] cr2: logging in
6472026-05-20T01:20:12.703ZMay 20 01:20:12.680 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6482026-05-20T01:20:22.281ZMay 20 01:20:22.258 DEBG [sc] cr2: starting
6492026-05-20T01:20:22.281ZMay 20 01:20:22.258 DEBG [sc] cr2: connecting to [::1]:56559
6502026-05-20T01:20:22.315ZMay 20 01:20:22.259 DEBG [sc] cr2 waiting for prompt
6512026-05-20T01:20:22.315ZMay 20 01:20:22.269 DEBG [sc] cr2: logging in
6522026-05-20T01:20:22.433ZMay 20 01:20:22.413 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6532026-05-20T01:20:24.533ZMay 20 01:20:24.514 INFO cr2: executing eos script show version
6542026-05-20T01:20:24.533ZMay 20 01:20:24.515 DEBG [sc] cr2: starting
6552026-05-20T01:20:24.533ZMay 20 01:20:24.515 DEBG [sc] cr2: connecting to [::1]:56559
6562026-05-20T01:20:24.569ZMay 20 01:20:24.515 DEBG [sc] cr2 waiting for prompt
6572026-05-20T01:20:24.569ZMay 20 01:20:24.525 DEBG [sc] cr2: logging in
6582026-05-20T01:20:24.723ZMay 20 01:20:24.702 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6592026-05-20T01:20:27.095ZMay 20 01:20:27.076 DEBG [sc] cr2: starting
6602026-05-20T01:20:27.095ZMay 20 01:20:27.076 DEBG [sc] cr2: connecting to [::1]:56559
6612026-05-20T01:20:27.134ZMay 20 01:20:27.077 DEBG [sc] cr2 waiting for prompt
6622026-05-20T01:20:27.134ZMay 20 01:20:27.088 DEBG [sc] cr2: logging in
6632026-05-20T01:20:27.255ZMay 20 01:20:27.232 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6642026-05-20T01:20:29.379ZMay 20 01:20:29.358 INFO cr2: executing eos script show version
6652026-05-20T01:20:29.379ZMay 20 01:20:29.358 DEBG [sc] cr2: starting
6662026-05-20T01:20:29.379ZMay 20 01:20:29.358 DEBG [sc] cr2: connecting to [::1]:56559
6672026-05-20T01:20:29.449ZMay 20 01:20:29.359 DEBG [sc] cr2 waiting for prompt
6682026-05-20T01:20:29.449ZMay 20 01:20:29.369 DEBG [sc] cr2: logging in
6692026-05-20T01:20:29.540ZMay 20 01:20:29.523 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6702026-05-20T01:20:30.248ZMay 20 01:20:30.226 DEBG [sc] ox: starting
6712026-05-20T01:20:30.248ZMay 20 01:20:30.226 DEBG [sc] ox: connecting to [::1]:64677
6722026-05-20T01:20:30.283ZMay 20 01:20:30.227 DEBG [sc] ox waiting for prompt
6732026-05-20T01:20:30.283ZMay 20 01:20:30.237 DEBG [sc] ox: logging in
6742026-05-20T01:20:30.333ZMay 20 01:20:30.315 DEBG [sc] ox: executing command `chmod +x npuvm`
6752026-05-20T01:20:30.400ZMay 20 01:20:30.383 DEBG [sc] ox: starting
6762026-05-20T01:20:30.400ZMay 20 01:20:30.383 DEBG [sc] ox: connecting to [::1]:64677
6772026-05-20T01:20:30.432ZMay 20 01:20:30.384 DEBG [sc] ox waiting for prompt
6782026-05-20T01:20:30.432ZMay 20 01:20:30.393 DEBG [sc] ox: logging in
6792026-05-20T01:20:30.490ZMay 20 01:20:30.470 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
6802026-05-20T01:20:32.081ZMay 20 01:20:32.060 INFO cr2: executing eos script
6812026-05-20T01:20:32.081Z enable
6822026-05-20T01:20:32.081Z configure
6832026-05-20T01:20:32.081Z ip routing
6842026-05-20T01:20:32.081Z ipv6 unicast-routing
6852026-05-20T01:20:32.081Z interface Ethernet1
6862026-05-20T01:20:32.081Z no switchport
6872026-05-20T01:20:32.081Z ip address 10.0.1.2/24
6882026-05-20T01:20:32.081Z ipv6 enable
6892026-05-20T01:20:32.081Z ipv6 address fd00:2::2/64
6902026-05-20T01:20:32.081Z bfd interval 300 min-rx 300 multiplier 3
6912026-05-20T01:20:32.081Z exit
6922026-05-20T01:20:32.082Z ip route 100.64.0.0/24 10.0.1.1 track bfd
6932026-05-20T01:20:32.082Z ipv6 route 3fff::/64 fd00:2::1 track bfd
6942026-05-20T01:20:32.082Z exit
6952026-05-20T01:20:32.082Z
6962026-05-20T01:20:32.082ZMay 20 01:20:32.060 DEBG [sc] cr2: starting
6972026-05-20T01:20:32.082ZMay 20 01:20:32.060 DEBG [sc] cr2: connecting to [::1]:56559
6982026-05-20T01:20:32.119ZMay 20 01:20:32.061 DEBG [sc] cr2 waiting for prompt
6992026-05-20T01:20:32.119ZMay 20 01:20:32.071 DEBG [sc] cr2: logging in
7002026-05-20T01:20:32.233ZMay 20 01:20:32.213 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
7012026-05-20T01:20:32.233Z enable
7022026-05-20T01:20:32.233Z configure
7032026-05-20T01:20:32.233Z ip routing
7042026-05-20T01:20:32.233Z ipv6 unicast-routing
7052026-05-20T01:20:32.233Z interface Ethernet1
7062026-05-20T01:20:32.233Z no switchport
7072026-05-20T01:20:32.233Z ip address 10.0.1.2/24
7082026-05-20T01:20:32.233Z ipv6 enable
7092026-05-20T01:20:32.233Z ipv6 address fd00:2::2/64
7102026-05-20T01:20:32.233Z bfd interval 300 min-rx 300 multiplier 3
7112026-05-20T01:20:32.233Z exit
7122026-05-20T01:20:32.233Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7132026-05-20T01:20:32.233Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7142026-05-20T01:20:32.234Z exit
7152026-05-20T01:20:32.234Z '`
7162026-05-20T01:20:48.430ZMay 20 01:20:48.398 INFO cr1: enabling frr daemon bfdd
7172026-05-20T01:20:48.430ZMay 20 01:20:48.398 DEBG [sc] cr1: starting
7182026-05-20T01:20:48.430ZMay 20 01:20:48.398 DEBG [sc] cr1: connecting to [::1]:55766
7192026-05-20T01:20:48.463ZMay 20 01:20:48.399 DEBG [sc] cr1 waiting for prompt
7202026-05-20T01:20:48.463ZMay 20 01:20:48.409 DEBG [sc] cr1: logging in
7212026-05-20T01:20:48.563ZMay 20 01:20:48.540 DEBG [sc] cr1: executing command `sed -i 's/bfdd=no/bfdd=yes/g' /etc/frr/daemons`
7222026-05-20T01:20:50.642ZMay 20 01:20:50.626 DEBG [sc] cr1: starting
7232026-05-20T01:20:50.642ZMay 20 01:20:50.626 DEBG [sc] cr1: connecting to [::1]:55766
7242026-05-20T01:20:50.674ZMay 20 01:20:50.626 DEBG [sc] cr1 waiting for prompt
7252026-05-20T01:20:50.674ZMay 20 01:20:50.636 DEBG [sc] cr1: logging in
7262026-05-20T01:20:50.800ZMay 20 01:20:50.780 DEBG [sc] cr1: executing command `systemctl restart frr`
7272026-05-20T01:20:58.435ZMay 20 01:20:58.415 INFO cr1: executing frr script
7282026-05-20T01:20:58.435Z configure
7292026-05-20T01:20:58.435Z interface enp0s8
7302026-05-20T01:20:58.435Z ip address 10.0.0.2/24
7312026-05-20T01:20:58.435Z ipv6 address fd00:1::2/64
7322026-05-20T01:20:58.435Z no shutdown
7332026-05-20T01:20:58.435Z exit
7342026-05-20T01:20:58.435Z bfd
7352026-05-20T01:20:58.435Z peer 10.0.0.1 local-address 10.0.0.2
7362026-05-20T01:20:58.435Z detect-multiplier 3
7372026-05-20T01:20:58.435Z receive-interval 300
7382026-05-20T01:20:58.435Z transmit-interval 300
7392026-05-20T01:20:58.435Z no shutdown
7402026-05-20T01:20:58.435Z exit
7412026-05-20T01:20:58.435Z peer fd00:1::1 local-address fd00:1::2
7422026-05-20T01:20:58.435Z detect-multiplier 3
7432026-05-20T01:20:58.435Z receive-interval 300
7442026-05-20T01:20:58.435Z transmit-interval 300
7452026-05-20T01:20:58.435Z no shutdown
7462026-05-20T01:20:58.435Z exit
7472026-05-20T01:20:58.435Z exit
7482026-05-20T01:20:58.435Z
7492026-05-20T01:20:58.435ZMay 20 01:20:58.415 DEBG [sc] cr1: starting
7502026-05-20T01:20:58.435ZMay 20 01:20:58.415 DEBG [sc] cr1: connecting to [::1]:55766
7512026-05-20T01:20:58.471ZMay 20 01:20:58.415 DEBG [sc] cr1 waiting for prompt
7522026-05-20T01:20:58.471ZMay 20 01:20:58.426 DEBG [sc] cr1: logging in
7532026-05-20T01:20:58.583ZMay 20 01:20:58.559 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 ' '`
7542026-05-20T01:22:41.211ZMay 20 01:22:41.195 DEBG [sc] ox: starting
7552026-05-20T01:22:41.211ZMay 20 01:22:41.195 DEBG [sc] ox: connecting to [::1]:64677
7562026-05-20T01:22:41.242ZMay 20 01:22:41.195 DEBG [sc] ox waiting for prompt
7572026-05-20T01:22:41.242ZMay 20 01:22:41.206 DEBG [sc] ox: logging in
7582026-05-20T01:22:41.301ZMay 20 01:22:41.282 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
7592026-05-20T01:22:41.540ZMay 20 01:22:41.522 DEBG [sc] ox: starting
7602026-05-20T01:22:41.571ZMay 20 01:22:41.522 DEBG [sc] ox: connecting to [::1]:64677
7612026-05-20T01:22:41.571ZMay 20 01:22:41.523 DEBG [sc] ox waiting for prompt
7622026-05-20T01:22:41.571ZMay 20 01:22:41.534 DEBG [sc] ox: logging in
7632026-05-20T01:22:41.627ZMay 20 01:22:41.610 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7642026-05-20T01:22:42.650ZMay 20 01:22:42.634 DEBG [sc] ox: starting
7652026-05-20T01:22:42.650ZMay 20 01:22:42.634 DEBG [sc] ox: connecting to [::1]:64677
7662026-05-20T01:22:42.681ZMay 20 01:22:42.635 DEBG [sc] ox waiting for prompt
7672026-05-20T01:22:42.681ZMay 20 01:22:42.635 DEBG [sc] ox: logging in
7682026-05-20T01:22:42.739ZMay 20 01:22:42.723 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7692026-05-20T01:22:42.805ZMay 20 01:22:42.788 DEBG [sc] ox: starting
7702026-05-20T01:22:42.806ZMay 20 01:22:42.788 DEBG [sc] ox: connecting to [::1]:64677
7712026-05-20T01:22:42.836ZMay 20 01:22:42.789 DEBG [sc] ox waiting for prompt
7722026-05-20T01:22:42.836ZMay 20 01:22:42.799 DEBG [sc] ox: logging in
7732026-05-20T01:22:42.895ZMay 20 01:22:42.878 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7742026-05-20T01:22:43.364ZMay 20 01:22:43.347 DEBG [sc] ox: starting
7752026-05-20T01:22:43.364ZMay 20 01:22:43.347 DEBG [sc] ox: connecting to [::1]:64677
7762026-05-20T01:22:43.397ZMay 20 01:22:43.348 DEBG [sc] ox waiting for prompt
7772026-05-20T01:22:43.397ZMay 20 01:22:43.359 DEBG [sc] ox: logging in
7782026-05-20T01:22:43.453ZMay 20 01:22:43.436 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
7792026-05-20T01:22:43.510ZMay 20 01:22:43.492 DEBG [sc] ox: starting
7802026-05-20T01:22:43.510ZMay 20 01:22:43.492 DEBG [sc] ox: connecting to [::1]:64677
7812026-05-20T01:22:43.541ZMay 20 01:22:43.493 DEBG [sc] ox waiting for prompt
7822026-05-20T01:22:43.541ZMay 20 01:22:43.502 DEBG [sc] ox: logging in
7832026-05-20T01:22:43.597ZMay 20 01:22:43.580 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
7842026-05-20T01:22:43.653ZMay 20 01:22:43.636 DEBG [sc] ox: starting
7852026-05-20T01:22:43.653ZMay 20 01:22:43.636 DEBG [sc] ox: connecting to [::1]:64677
7862026-05-20T01:22:43.693ZMay 20 01:22:43.637 DEBG [sc] ox waiting for prompt
7872026-05-20T01:22:43.693ZMay 20 01:22:43.648 DEBG [sc] ox: logging in
7882026-05-20T01:22:43.748ZMay 20 01:22:43.725 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.0.1/24 tfportqsfp0_0/v4`
7892026-05-20T01:22:44.274ZMay 20 01:22:44.257 DEBG [sc] ox: starting
7902026-05-20T01:22:44.274ZMay 20 01:22:44.257 DEBG [sc] ox: connecting to [::1]:64677
7912026-05-20T01:22:44.305ZMay 20 01:22:44.258 DEBG [sc] ox waiting for prompt
7922026-05-20T01:22:44.305ZMay 20 01:22:44.268 DEBG [sc] ox: logging in
7932026-05-20T01:22:44.364ZMay 20 01:22:44.345 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v4 -p -o addr`
7942026-05-20T01:22:44.440ZMay 20 01:22:44.399 DEBG [sc] ox: starting
7952026-05-20T01:22:44.440ZMay 20 01:22:44.400 DEBG [sc] ox: connecting to [::1]:64677
7962026-05-20T01:22:44.440ZMay 20 01:22:44.400 DEBG [sc] ox waiting for prompt
7972026-05-20T01:22:44.440ZMay 20 01:22:44.411 DEBG [sc] ox: logging in
7982026-05-20T01:22:44.505ZMay 20 01:22:44.487 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:1::1/64 tfportqsfp0_0/v6`
7992026-05-20T01:22:45.019ZMay 20 01:22:44.999 DEBG [sc] ox: starting
8002026-05-20T01:22:45.019ZMay 20 01:22:44.999 DEBG [sc] ox: connecting to [::1]:64677
8012026-05-20T01:22:45.052ZMay 20 01:22:45.001 DEBG [sc] ox waiting for prompt
8022026-05-20T01:22:45.052ZMay 20 01:22:45.011 DEBG [sc] ox: logging in
8032026-05-20T01:22:45.105ZMay 20 01:22:45.088 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v6 -p -o addr`
8042026-05-20T01:22:45.161ZMay 20 01:22:45.144 DEBG [sc] ox: starting
8052026-05-20T01:22:45.161ZMay 20 01:22:45.144 DEBG [sc] ox: connecting to [::1]:64677
8062026-05-20T01:22:45.191ZMay 20 01:22:45.144 DEBG [sc] ox waiting for prompt
8072026-05-20T01:22:45.191ZMay 20 01:22:45.155 DEBG [sc] ox: logging in
8082026-05-20T01:22:45.248ZMay 20 01:22:45.232 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
8092026-05-20T01:22:45.309ZMay 20 01:22:45.287 DEBG [sc] ox: starting
8102026-05-20T01:22:45.309ZMay 20 01:22:45.287 DEBG [sc] ox: connecting to [::1]:64677
8112026-05-20T01:22:45.340ZMay 20 01:22:45.287 DEBG [sc] ox waiting for prompt
8122026-05-20T01:22:45.340ZMay 20 01:22:45.298 DEBG [sc] ox: logging in
8132026-05-20T01:22:45.391ZMay 20 01:22:45.375 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
8142026-05-20T01:22:45.447ZMay 20 01:22:45.430 DEBG [sc] ox: starting
8152026-05-20T01:22:45.447ZMay 20 01:22:45.430 DEBG [sc] ox: connecting to [::1]:64677
8162026-05-20T01:22:45.484ZMay 20 01:22:45.431 DEBG [sc] ox waiting for prompt
8172026-05-20T01:22:45.484ZMay 20 01:22:45.441 DEBG [sc] ox: logging in
8182026-05-20T01:22:45.550ZMay 20 01:22:45.529 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.1.1/24 tfportqsfp1_0/v4`
8192026-05-20T01:22:46.083ZMay 20 01:22:46.060 DEBG [sc] ox: starting
8202026-05-20T01:22:46.083ZMay 20 01:22:46.060 DEBG [sc] ox: connecting to [::1]:64677
8212026-05-20T01:22:46.117ZMay 20 01:22:46.061 DEBG [sc] ox waiting for prompt
8222026-05-20T01:22:46.117ZMay 20 01:22:46.071 DEBG [sc] ox: logging in
8232026-05-20T01:22:46.167ZMay 20 01:22:46.149 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v4 -p -o addr`
8242026-05-20T01:22:46.222ZMay 20 01:22:46.204 DEBG [sc] ox: starting
8252026-05-20T01:22:46.223ZMay 20 01:22:46.204 DEBG [sc] ox: connecting to [::1]:64677
8262026-05-20T01:22:46.254ZMay 20 01:22:46.204 DEBG [sc] ox waiting for prompt
8272026-05-20T01:22:46.255ZMay 20 01:22:46.215 DEBG [sc] ox: logging in
8282026-05-20T01:22:46.312ZMay 20 01:22:46.292 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:2::1/64 tfportqsfp1_0/v6`
8292026-05-20T01:22:46.834ZMay 20 01:22:46.815 DEBG [sc] ox: starting
8302026-05-20T01:22:46.834ZMay 20 01:22:46.815 DEBG [sc] ox: connecting to [::1]:64677
8312026-05-20T01:22:46.865ZMay 20 01:22:46.816 DEBG [sc] ox waiting for prompt
8322026-05-20T01:22:46.865ZMay 20 01:22:46.826 DEBG [sc] ox: logging in
8332026-05-20T01:22:46.926ZMay 20 01:22:46.903 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v6 -p -o addr`
8342026-05-20T01:22:46.992ZMay 20 01:22:46.969 DEBG [sc] ox: starting
8352026-05-20T01:22:46.992ZMay 20 01:22:46.969 DEBG [sc] ox: connecting to [::1]:64677
8362026-05-20T01:22:47.024ZMay 20 01:22:46.970 DEBG [sc] ox waiting for prompt
8372026-05-20T01:22:47.025ZMay 20 01:22:46.980 DEBG [sc] ox: logging in
8382026-05-20T01:22:47.073ZMay 20 01:22:47.057 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
8392026-05-20T01:22:47.131ZMay 20 01:22:47.112 DEBG [sc] ox: starting
8402026-05-20T01:22:47.131ZMay 20 01:22:47.112 DEBG [sc] ox: connecting to [::1]:64677
8412026-05-20T01:22:47.165ZMay 20 01:22:47.113 DEBG [sc] ox waiting for prompt
8422026-05-20T01:22:47.165ZMay 20 01:22:47.122 DEBG [sc] ox: logging in
8432026-05-20T01:22:47.219ZMay 20 01:22:47.200 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
8442026-05-20T01:22:47.300ZMay 20 01:22:47.259 INFO installing static v4 route 192.168.100.0/24
8452026-05-20T01:22:47.353ZMay 20 01:22:47.260 INFO installing static v6 route fd01::/64
8462026-05-20T01:22:47.353ZMay 20 01:22:47.261 INFO adding BFD peers for cr1 and cr2 (dual-stack)
8472026-05-20T01:22:47.353ZMay 20 01:22:47.264 INFO phase 1: both peers up
8482026-05-20T01:22:48.287ZMay 20 01:22:48.267 INFO cr1: executing frr script show bfd peers json
8492026-05-20T01:22:48.287ZMay 20 01:22:48.267 DEBG [sc] cr1: starting
8502026-05-20T01:22:48.287ZMay 20 01:22:48.267 DEBG [sc] cr1: connecting to [::1]:55766
8512026-05-20T01:22:48.323ZMay 20 01:22:48.268 DEBG [sc] cr1 waiting for prompt
8522026-05-20T01:22:48.323ZMay 20 01:22:48.278 DEBG [sc] cr1: logging in
8532026-05-20T01:22:48.625ZMay 20 01:22:48.592 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8542026-05-20T01:22:50.816ZMay 20 01:22:50.729 INFO cr1: executing frr script show bfd peers json
8552026-05-20T01:22:50.816ZMay 20 01:22:50.729 DEBG [sc] cr1: starting
8562026-05-20T01:22:50.816ZMay 20 01:22:50.729 DEBG [sc] cr1: connecting to [::1]:55766
8572026-05-20T01:22:50.908ZMay 20 01:22:50.730 DEBG [sc] cr1 waiting for prompt
8582026-05-20T01:22:50.908ZMay 20 01:22:50.739 DEBG [sc] cr1: logging in
8592026-05-20T01:22:50.973ZMay 20 01:22:50.873 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8602026-05-20T01:22:53.047ZMay 20 01:22:53.015 INFO cr2: executing eos script show bfd peers | json
8612026-05-20T01:22:53.047ZMay 20 01:22:53.015 DEBG [sc] cr2: starting
8622026-05-20T01:22:53.047ZMay 20 01:22:53.015 DEBG [sc] cr2: connecting to [::1]:56559
8632026-05-20T01:22:53.094ZMay 20 01:22:53.016 DEBG [sc] cr2 waiting for prompt
8642026-05-20T01:22:53.094ZMay 20 01:22:53.027 DEBG [sc] cr2: logging in
8652026-05-20T01:22:53.363ZMay 20 01:22:53.336 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8662026-05-20T01:22:55.701ZMay 20 01:22:55.685 INFO cr2: executing eos script show bfd peers | json
8672026-05-20T01:22:55.701ZMay 20 01:22:55.685 DEBG [sc] cr2: starting
8682026-05-20T01:22:55.701ZMay 20 01:22:55.685 DEBG [sc] cr2: connecting to [::1]:56559
8692026-05-20T01:22:55.734ZMay 20 01:22:55.685 DEBG [sc] cr2 waiting for prompt
8702026-05-20T01:22:55.734ZMay 20 01:22:55.695 DEBG [sc] cr2: logging in
8712026-05-20T01:22:55.855ZMay 20 01:22:55.838 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8722026-05-20T01:22:58.190ZMay 20 01:22:58.171 INFO phase 2: pause bfdd on cr1
8732026-05-20T01:22:58.190ZMay 20 01:22:58.171 INFO cr1: pausing frr bfdd
8742026-05-20T01:22:58.224ZMay 20 01:22:58.171 DEBG [sc] cr1: starting
8752026-05-20T01:22:58.224ZMay 20 01:22:58.171 DEBG [sc] cr1: connecting to [::1]:55766
8762026-05-20T01:22:58.224ZMay 20 01:22:58.172 DEBG [sc] cr1 waiting for prompt
8772026-05-20T01:22:58.224ZMay 20 01:22:58.183 DEBG [sc] cr1: logging in
8782026-05-20T01:22:58.385ZMay 20 01:22:58.366 DEBG [sc] cr1: executing command `pkill -STOP bfdd`
8792026-05-20T01:23:00.472ZMay 20 01:23:00.454 INFO cr2: executing eos script show bfd peers | json
8802026-05-20T01:23:00.472ZMay 20 01:23:00.454 DEBG [sc] cr2: starting
8812026-05-20T01:23:00.513ZMay 20 01:23:00.454 DEBG [sc] cr2: connecting to [::1]:56559
8822026-05-20T01:23:00.513ZMay 20 01:23:00.454 DEBG [sc] cr2 waiting for prompt
8832026-05-20T01:23:00.513ZMay 20 01:23:00.466 DEBG [sc] cr2: logging in
8842026-05-20T01:23:00.648ZMay 20 01:23:00.630 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8852026-05-20T01:23:02.980ZMay 20 01:23:02.960 INFO cr2: executing eos script show bfd peers | json
8862026-05-20T01:23:02.980ZMay 20 01:23:02.961 DEBG [sc] cr2: starting
8872026-05-20T01:23:03.017ZMay 20 01:23:02.961 DEBG [sc] cr2: connecting to [::1]:56559
8882026-05-20T01:23:03.017ZMay 20 01:23:02.961 DEBG [sc] cr2 waiting for prompt
8892026-05-20T01:23:03.017ZMay 20 01:23:02.972 DEBG [sc] cr2: logging in
8902026-05-20T01:23:03.132ZMay 20 01:23:03.115 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8912026-05-20T01:23:05.481ZMay 20 01:23:05.463 INFO phase 3: pause ceos on cr2
8922026-05-20T01:23:05.481ZMay 20 01:23:05.463 INFO cr2: pausing ceos
8932026-05-20T01:23:05.481ZMay 20 01:23:05.463 DEBG [sc] cr2: starting
8942026-05-20T01:23:05.481ZMay 20 01:23:05.463 DEBG [sc] cr2: connecting to [::1]:56559
8952026-05-20T01:23:05.512ZMay 20 01:23:05.464 DEBG [sc] cr2 waiting for prompt
8962026-05-20T01:23:05.512ZMay 20 01:23:05.473 DEBG [sc] cr2: logging in
8972026-05-20T01:23:05.644ZMay 20 01:23:05.627 DEBG [sc] cr2: executing command `docker pause ceos`
8982026-05-20T01:23:07.749ZMay 20 01:23:07.732 INFO phase 4: resume bfdd on cr1
8992026-05-20T01:23:07.749ZMay 20 01:23:07.732 INFO cr1: resuming frr bfdd
9002026-05-20T01:23:07.749ZMay 20 01:23:07.732 DEBG [sc] cr1: starting
9012026-05-20T01:23:07.749ZMay 20 01:23:07.732 DEBG [sc] cr1: connecting to [::1]:55766
9022026-05-20T01:23:07.784ZMay 20 01:23:07.732 DEBG [sc] cr1 waiting for prompt
9032026-05-20T01:23:07.784ZMay 20 01:23:07.743 DEBG [sc] cr1: logging in
9042026-05-20T01:23:07.894ZMay 20 01:23:07.875 DEBG [sc] cr1: executing command `pkill -CONT bfdd`
9052026-05-20T01:23:09.979ZMay 20 01:23:09.961 INFO cr1: executing frr script show bfd peers json
9062026-05-20T01:23:09.979ZMay 20 01:23:09.961 DEBG [sc] cr1: starting
9072026-05-20T01:23:09.979ZMay 20 01:23:09.961 DEBG [sc] cr1: connecting to [::1]:55766
9082026-05-20T01:23:10.018ZMay 20 01:23:09.962 DEBG [sc] cr1 waiting for prompt
9092026-05-20T01:23:10.018ZMay 20 01:23:09.970 DEBG [sc] cr1: logging in
9102026-05-20T01:23:10.145ZMay 20 01:23:10.126 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9112026-05-20T01:23:12.280ZMay 20 01:23:12.263 INFO cr1: executing frr script show bfd peers json
9122026-05-20T01:23:12.281ZMay 20 01:23:12.263 DEBG [sc] cr1: starting
9132026-05-20T01:23:12.281ZMay 20 01:23:12.263 DEBG [sc] cr1: connecting to [::1]:55766
9142026-05-20T01:23:12.313ZMay 20 01:23:12.264 DEBG [sc] cr1 waiting for prompt
9152026-05-20T01:23:12.313ZMay 20 01:23:12.274 DEBG [sc] cr1: logging in
9162026-05-20T01:23:12.435ZMay 20 01:23:12.417 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9172026-05-20T01:23:14.569ZMay 20 01:23:14.548 INFO phase 5: unpause ceos on cr2
9182026-05-20T01:23:14.569ZMay 20 01:23:14.548 INFO cr2: unpausing ceos
9192026-05-20T01:23:14.569ZMay 20 01:23:14.548 DEBG [sc] cr2: starting
9202026-05-20T01:23:14.569ZMay 20 01:23:14.548 DEBG [sc] cr2: connecting to [::1]:56559
9212026-05-20T01:23:14.602ZMay 20 01:23:14.549 DEBG [sc] cr2 waiting for prompt
9222026-05-20T01:23:14.602ZMay 20 01:23:14.560 DEBG [sc] cr2: logging in
9232026-05-20T01:23:14.715ZMay 20 01:23:14.693 DEBG [sc] cr2: executing command `docker unpause ceos`
9242026-05-20T01:23:16.821ZMay 20 01:23:16.803 INFO cr1: executing frr script show bfd peers json
9252026-05-20T01:23:16.821ZMay 20 01:23:16.803 DEBG [sc] cr1: starting
9262026-05-20T01:23:16.821ZMay 20 01:23:16.803 DEBG [sc] cr1: connecting to [::1]:55766
9272026-05-20T01:23:16.852ZMay 20 01:23:16.803 DEBG [sc] cr1 waiting for prompt
9282026-05-20T01:23:16.852ZMay 20 01:23:16.815 DEBG [sc] cr1: logging in
9292026-05-20T01:23:16.977ZMay 20 01:23:16.959 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9302026-05-20T01:23:19.116ZMay 20 01:23:19.098 INFO cr1: executing frr script show bfd peers json
9312026-05-20T01:23:19.116ZMay 20 01:23:19.098 DEBG [sc] cr1: starting
9322026-05-20T01:23:19.116ZMay 20 01:23:19.098 DEBG [sc] cr1: connecting to [::1]:55766
9332026-05-20T01:23:19.153ZMay 20 01:23:19.099 DEBG [sc] cr1 waiting for prompt
9342026-05-20T01:23:19.153ZMay 20 01:23:19.110 DEBG [sc] cr1: logging in
9352026-05-20T01:23:19.292ZMay 20 01:23:19.275 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9362026-05-20T01:23:21.444ZMay 20 01:23:21.426 INFO cr2: executing eos script show bfd peers | json
9372026-05-20T01:23:21.444ZMay 20 01:23:21.426 DEBG [sc] cr2: starting
9382026-05-20T01:23:21.444ZMay 20 01:23:21.426 DEBG [sc] cr2: connecting to [::1]:56559
9392026-05-20T01:23:21.474ZMay 20 01:23:21.427 DEBG [sc] cr2 waiting for prompt
9402026-05-20T01:23:21.474ZMay 20 01:23:21.437 DEBG [sc] cr2: logging in
9412026-05-20T01:23:21.600ZMay 20 01:23:21.581 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9422026-05-20T01:23:23.924ZMay 20 01:23:23.905 INFO cr2: executing eos script show bfd peers | json
9432026-05-20T01:23:23.924ZMay 20 01:23:23.906 DEBG [sc] cr2: starting
9442026-05-20T01:23:23.924ZMay 20 01:23:23.906 DEBG [sc] cr2: connecting to [::1]:56559
9452026-05-20T01:23:23.959ZMay 20 01:23:23.906 DEBG [sc] cr2 waiting for prompt
9462026-05-20T01:23:23.959ZMay 20 01:23:23.917 DEBG [sc] cr2: logging in
9472026-05-20T01:23:24.075ZMay 20 01:23:24.049 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9482026-05-20T01:23:26.414ZMay 20 01:23:26.393 INFO trio bfd static routing test passed 🎉
9492026-05-20T01:23:26.414ZMay 20 01:23:26.394 INFO destroying runner for deployment mgtriobfd
9502026-05-20T01:23:26.414ZMay 20 01:23:26.394 INFO destroying deployment mgtriobfd
9512026-05-20T01:23:26.414ZMay 20 01:23:26.394 INFO destroying nodes
9522026-05-20T01:23:26.505ZMay 20 01:23:26.486 INFO destroying links
9532026-05-20T01:23:26.505ZMay 20 01:23:26.486 INFO destroying link mgtriobfd_ox_sn_vnic0
9542026-05-20T01:23:26.544ZMay 20 01:23:26.488 INFO destroying link mgtriobfd_ox_sn_sim0
9552026-05-20T01:23:26.544ZMay 20 01:23:26.490 INFO destroying link mgtriobfd_cr1_vn_vnic0
9562026-05-20T01:23:27.509ZMay 20 01:23:27.492 INFO destroying link mgtriobfd_cr1_vn_sim0
9572026-05-20T01:23:27.542ZMay 20 01:23:27.493 INFO destroying link mgtriobfd_ox_sn_vnic1
9582026-05-20T01:23:27.542ZMay 20 01:23:27.494 INFO destroying link mgtriobfd_ox_sn_sim1
9592026-05-20T01:23:27.542ZMay 20 01:23:27.495 INFO destroying link mgtriobfd_cr2_vn_vnic0
9602026-05-20T01:23:27.542ZMay 20 01:23:27.496 INFO destroying link mgtriobfd_cr2_vn_sim0
9612026-05-20T01:23:27.542ZMay 20 01:23:27.497 INFO destroying external links
9622026-05-20T01:23:27.542ZMay 20 01:23:27.497 INFO destroying external link mgtriobfd_ox_vn_vnic2
9632026-05-20T01:23:27.542ZMay 20 01:23:27.498 INFO destroying external link mgtriobfd_cr1_vn_vnic1
9642026-05-20T01:23:27.542ZMay 20 01:23:27.500 INFO destroying external link mgtriobfd_cr2_vn_vnic1
9652026-05-20T01:23:27.543ZMay 20 01:23:27.501 INFO destroying images
9662026-05-20T01:23:28.007ZMay 20 01:23:27.989 INFO destroying workspace at .falcon
9672026-05-20T01:23:28.038Zprocess exited: duration 900637 ms, exit code 0
 
9682026-05-20T01:23:28.103Zfound 0 output files