01KRPVXE7DYHQ7Q0TPW2VVT97H: falcon

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

Buildomat Job: 01KRPVXWYKAFGTAYFSHEB3JP4A

Tags:

Output:

SEQ GLOBAL TIME DETAILS
12026-05-15T22:38:59.384Zjob dependencies complete; ready to run (waiting for 13 m 9 s)
22026-05-15T22:42:13.391Zjob assigned to worker 01KRPWP16048H7FXT1BPQ1ZEXS [factory edgar, gimlet/BRM42220010/961] (queued for 3 m 14 s)
32026-05-15T22:42:13.690Zdownloading input: /input/build/work/debug/ddmadm
42026-05-15T22:42:36.789Zdownloaded input: /input/build/work/debug/ddmadm
52026-05-15T22:42:36.789Zdownloading input: /input/build/work/debug/ddmd
62026-05-15T22:43:04.537Zdownloaded input: /input/build/work/debug/ddmd
72026-05-15T22:43:04.537Zdownloading input: /input/build/work/debug/mgadm
82026-05-15T22:43:31.849Zdownloaded input: /input/build/work/debug/mgadm
92026-05-15T22:43:31.849Zdownloading input: /input/build/work/debug/mgd
102026-05-15T22:44:03.264Zdownloaded input: /input/build/work/debug/mgd
112026-05-15T22:44:03.288Zdownloading input: /input/build/work/release/ddmadm
122026-05-15T22:44:05.420Zdownloaded input: /input/build/work/release/ddmadm
132026-05-15T22:44:05.420Zdownloading input: /input/build/work/release/ddmd
142026-05-15T22:44:08.045Zdownloaded input: /input/build/work/release/ddmd
152026-05-15T22:44:08.070Zdownloading input: /input/build/work/release/falcon-lab
162026-05-15T22:44:09.695Zdownloaded input: /input/build/work/release/falcon-lab
172026-05-15T22:44:09.695Zdownloading input: /input/build/work/release/mgadm
182026-05-15T22:44:12.316Zdownloaded input: /input/build/work/release/mgadm
192026-05-15T22:44:12.316Zdownloading input: /input/build/work/release/mgd
202026-05-15T22:44:15.611Zdownloaded input: /input/build/work/release/mgd
212026-05-15T22:44:15.635Zdownloading input: /input/build-interop/work/testbed.tar.gz
222026-05-15T22:44:24.640Zdownloaded input: /input/build-interop/work/testbed.tar.gz
232026-05-15T22:44:24.640Zdownloading input: /input/build-interop/work/dhcp-server
242026-05-15T22:44:27.203Zdownloaded input: /input/build-interop/work/dhcp-server
 
252026-05-15T22:44:27.203Zstarting task 0: "setup"
262026-05-15T22:44:27.228Z++ uname -s
272026-05-15T22:44:27.228Z+ kern=SunOS
282026-05-15T22:44:27.228Z+ build_user=build
292026-05-15T22:44:27.228Z+ build_uid=12345
302026-05-15T22:44:27.228Z+ work_dir=/work
312026-05-15T22:44:27.228Z+ input_dir=/input
322026-05-15T22:44:27.228Z+ [[ 0 == 12345 ]]
332026-05-15T22:44:27.228Z+ case "$kern" in
342026-05-15T22:44:27.228Z+ groupadd -g 12345 build
352026-05-15T22:44:27.252Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
362026-05-15T22:44:29.241Z+ zfs create -o mountpoint=/work rpool/work
372026-05-15T22:44:29.279Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
382026-05-15T22:44:29.303Z+ home_fs=
392026-05-15T22:44:29.303Z+ [[ '' == autofs ]]
402026-05-15T22:44:29.303Z+ mkdir -p /home/build
412026-05-15T22:44:29.303Z+ chown build:build /home/build /work
422026-05-15T22:44:31.292Z+ chmod 0700 /home/build /work
432026-05-15T22:44:31.316Zprocess exited: duration 4092 ms, exit code 0
 
442026-05-15T22:44:31.364Zstarting task 1: "authentication"
452026-05-15T22:44:31.460Zprocess exited: duration 95 ms, exit code 0
 
462026-05-15T22:44:31.509Zstarting task 2: "build"
472026-05-15T22:44:31.533Z+ set -e
482026-05-15T22:44:31.534Z+ banner zpool
492026-05-15T22:44:31.534Z
502026-05-15T22:44:31.534Z ###### ##### #### #### #
512026-05-15T22:44:31.534Z # # # # # # # #
522026-05-15T22:44:31.534Z # # # # # # # #
532026-05-15T22:44:31.534Z # ##### # # # # #
542026-05-15T22:44:31.534Z # # # # # # #
552026-05-15T22:44:31.534Z ###### # #### #### ######
562026-05-15T22:44:31.534Z
572026-05-15T22:44:31.534Z++ pfexec diskinfo -pH
582026-05-15T22:44:31.534Z++ sort -k8 -n -r
592026-05-15T22:44:31.558Z++ head -1
602026-05-15T22:44:31.558Z++ awk '{print $2}'
612026-05-15T22:44:31.582Z+ DISK=c9t0014EE81000BC3B1d0
622026-05-15T22:44:31.582Z+ export DISK
632026-05-15T22:44:31.582Z+ pfexec zpool create -o ashift=12 -f cpool c9t0014EE81000BC3B1d0
642026-05-15T22:44:31.647Z+ pfexec zfs create -o mountpoint=/ci cpool/ci
652026-05-15T22:44:31.674Z++ curl -s http://catacomb.eng.oxide.computer:12346/trim-me
662026-05-15T22:44:31.838Z+ [[ true =~ true ]]
672026-05-15T22:44:31.838Z+ pfexec zpool trim cpool
682026-05-15T22:44:31.862Z++ zpool status -t cpool
692026-05-15T22:44:31.887Z+ [[ ! pool: cpool
702026-05-15T22:44:31.887Z state: ONLINE
712026-05-15T22:44:31.887Z scan: none requested
722026-05-15T22:44:31.887Zconfig:
732026-05-15T22:44:31.887Z
742026-05-15T22:44:31.887Z NAME STATE READ WRITE CKSUM
752026-05-15T22:44:31.887Z cpool ONLINE 0 0 0
762026-05-15T22:44:31.887Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (1% trimmed, started at May 15, 2026 at 10:44:31 PM UTC)
772026-05-15T22:44:31.887Z
782026-05-15T22:44:31.887Zerrors: No known data errors =~ 100% ]]
792026-05-15T22:44:31.887Z+ sleep 10
802026-05-15T22:44:41.873Z++ zpool status -t cpool
812026-05-15T22:44:41.898Z+ [[ ! pool: cpool
822026-05-15T22:44:41.898Z state: ONLINE
832026-05-15T22:44:41.898Z scan: none requested
842026-05-15T22:44:41.898Zconfig:
852026-05-15T22:44:41.898Z
862026-05-15T22:44:41.898Z NAME STATE READ WRITE CKSUM
872026-05-15T22:44:41.898Z cpool ONLINE 0 0 0
882026-05-15T22:44:41.898Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (70% trimmed, started at May 15, 2026 at 10:44:31 PM UTC)
892026-05-15T22:44:41.898Z
902026-05-15T22:44:41.898Zerrors: No known data errors =~ 100% ]]
912026-05-15T22:44:41.898Z+ sleep 10
922026-05-15T22:44:51.889Z++ zpool status -t cpool
932026-05-15T22:44:51.914Z+ [[ ! pool: cpool
942026-05-15T22:44:51.914Z state: ONLINE
952026-05-15T22:44:51.914Z scan: none requested
962026-05-15T22:44:51.914Zconfig:
972026-05-15T22:44:51.914Z
982026-05-15T22:44:51.914Z NAME STATE READ WRITE CKSUM
992026-05-15T22:44:51.914Z cpool ONLINE 0 0 0
1002026-05-15T22:44:51.914Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (100% trimmed, completed at May 15, 2026 at 10:44:46 PM UTC)
1012026-05-15T22:44:51.914Z
1022026-05-15T22:44:51.914Zerrors: No known data errors =~ 100% ]]
1032026-05-15T22:44:51.914Z+ pfexec chown 12345 /ci
1042026-05-15T22:44:51.914Z+ cd /ci
1052026-05-15T22:44:51.914Z+ export FALCON_DATASET=cpool/falcon
1062026-05-15T22:44:51.914Z+ FALCON_DATASET=cpool/falcon
1072026-05-15T22:44:51.914Z+ banner setup
1082026-05-15T22:44:51.914Z
1092026-05-15T22:44:51.914Z #### ###### ##### # # #####
1102026-05-15T22:44:51.914Z # # # # # # #
1112026-05-15T22:44:51.914Z #### ##### # # # # #
1122026-05-15T22:44:51.914Z # # # # # #####
1132026-05-15T22:44:51.914Z # # # # # # #
1142026-05-15T22:44:51.914Z #### ###### # #### #
1152026-05-15T22:44:51.914Z
1162026-05-15T22:44:51.914Z+ cp /input/build-interop/work/dhcp-server .
1172026-05-15T22:44:51.942Z+ cp /input/build/work/release/falcon-lab .
1182026-05-15T22:44:51.980Z+ cp /input/build/work/release/mgd .
1192026-05-15T22:44:52.044Z+ cp /input/build/work/release/ddmd .
1202026-05-15T22:44:52.115Z+ chmod +x dhcp-server falcon-lab mgd ddmd
1212026-05-15T22:44:52.140Z+ mkdir -p cargo-bay
1222026-05-15T22:44:52.140Z+ mv mgd cargo-bay/
1232026-05-15T22:44:52.140Z+ mv ddmd cargo-bay/
1242026-05-15T22:44:52.140Z+ export EXT_INTERFACE=igb0
1252026-05-15T22:44:52.140Z+ EXT_INTERFACE=igb0
1262026-05-15T22:44:52.140Z++ bmat address ls -f extra -Ho first
1272026-05-15T22:44:52.164Z+ first=10.151.6.164
1282026-05-15T22:44:52.164Z++ bmat address ls -f extra -Ho last
1292026-05-15T22:44:52.189Z+ last=10.151.6.227
1302026-05-15T22:44:52.189Z++ bmat address ls -f extra -Ho gateway
1312026-05-15T22:44:52.213Z+ gw=10.151.6.1
1322026-05-15T22:44:52.213Z++ ipadm show-addr igb0/dhcp -po ADDR
1332026-05-15T22:44:52.213Z++ sed 's#/.*##g'
1342026-05-15T22:44:52.213Z+ server=10.151.6.100
1352026-05-15T22:44:52.238Z+ RUST_LOG=debug
1362026-05-15T22:44:52.238Z+ pfexec ./falcon-lab run trio-unnumbered
1372026-05-15T22:44:52.238Z+ pfexec ./dhcp-server 10.151.6.164 10.151.6.227 10.151.6.1 10.151.6.100
1382026-05-15T22:44:52.238ZMay 15 22:44:52.217 DEBG using default route interface igb0
1392026-05-15T22:44:52.238ZMay 15 22:44:52.218 DEBG using default route interface igb0
1402026-05-15T22:44:52.238ZMay 15 22:44:52.218 DEBG using default route interface igb0
1412026-05-15T22:44:52.238ZMay 15 22:44:52.218 INFO launching runner: deployment(mgtriou) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
1422026-05-15T22:44:52.238ZMay 15 22:44:52.218 INFO starting preflight for deployment mgtriou
1432026-05-15T22:44:52.238ZMay 15 22:44:52.218 INFO propolis-server binary not found
1442026-05-15T22:44:52.238ZMay 15 22:44:52.218 INFO downloading propolis server rev 36f20be9bb4c3b362029237f5feb6377c982395f, writing to .falcon/bin/propolis-server
1452026-05-15T22:44:56.067ZMay 15 22:44:56.049 INFO ovmf fd not found
1462026-05-15T22:44:56.067ZMay 15 22:44:56.049 INFO downloading ovmf
1472026-05-15T22:44:56.419ZMay 15 22:44:56.401 INFO base image for helios-2.9 does not exist, attempting to install
1482026-05-15T22:44:56.420ZMay 15 22:44:56.401 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/helios-2.9_0.raw.xz
1492026-05-15T22:45:25.203ZMay 15 22:45:25.182 INFO extracting image to /tmp/helios-2.9_0.raw
1502026-05-15T22:45:59.052ZMay 15 22:45:59.029 INFO creating zvol cpool/falcon/img/helios-2.9 of size 4508880896
1512026-05-15T22:45:59.099ZMay 15 22:45:59.077 INFO copying image data to zvol
1522026-05-15T22:46:09.608ZMay 15 22:46:09.586 INFO creating zfs snapshot cpool/falcon/img/helios-2.9@base
1532026-05-15T22:46:12.769ZMay 15 22:46:12.747 INFO base image for debian-13.2 does not exist, attempting to install
1542026-05-15T22:46:12.769ZMay 15 22:46:12.747 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz
1552026-05-15T22:46:34.532ZMay 15 22:46:34.510 INFO extracting image to /tmp/debian-13.2_0.raw
1562026-05-15T22:46:55.659ZMay 15 22:46:55.638 INFO creating zvol cpool/falcon/img/debian-13.2 of size 3221229568
1572026-05-15T22:46:55.686ZMay 15 22:46:55.665 INFO copying image data to zvol
1582026-05-15T22:47:01.890ZMay 15 22:47:01.869 INFO creating zfs snapshot cpool/falcon/img/debian-13.2@base
1592026-05-15T22:47:05.596ZMay 15 22:47:05.575 INFO base image for eos-4.35 does not exist, attempting to install
1602026-05-15T22:47:05.597ZMay 15 22:47:05.575 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz
1612026-05-15T22:47:49.664ZMay 15 22:47:49.643 INFO extracting image to /tmp/eos-4.35_0.raw
1622026-05-15T22:49:13.449ZMay 15 22:49:13.431 INFO creating zvol cpool/falcon/img/eos-4.35 of size 21474840576
1632026-05-15T22:49:13.475ZMay 15 22:49:13.458 INFO copying image data to zvol
1642026-05-15T22:50:01.870ZMay 15 22:50:01.853 INFO creating zfs snapshot cpool/falcon/img/eos-4.35@base
1652026-05-15T22:50:05.253ZMay 15 22:50:05.237 INFO creating links
1662026-05-15T22:50:05.253ZMay 15 22:50:05.237 DEBG destroying link mgtriou_ox_sn_vnic0
1672026-05-15T22:50:05.279ZMay 15 22:50:05.237 DEBG destroying link mgtriou_ox_sn_sim0
1682026-05-15T22:50:05.279ZMay 15 22:50:05.237 INFO creating simnet link 'mgtriou_ox_sn_sim0'
1692026-05-15T22:50:05.279ZMay 15 22:50:05.239 INFO creating vnic link 'mgtriou_ox_sn_vnic0'
1702026-05-15T22:50:05.279ZMay 15 22:50:05.246 DEBG link pair created
1712026-05-15T22:50:05.279ZMay 15 22:50:05.246 DEBG destroying link mgtriou_cr1_vn_vnic0
1722026-05-15T22:50:05.279ZMay 15 22:50:05.246 DEBG destroying link mgtriou_cr1_vn_sim0
1732026-05-15T22:50:05.279ZMay 15 22:50:05.246 INFO creating simnet link 'mgtriou_cr1_vn_sim0'
1742026-05-15T22:50:05.280ZMay 15 22:50:05.247 INFO creating vnic link 'mgtriou_cr1_vn_vnic0'
1752026-05-15T22:50:05.280ZMay 15 22:50:05.254 DEBG link pair created
1762026-05-15T22:50:05.280ZMay 15 22:50:05.254 DEBG destroying link mgtriou_ox_sn_vnic1
1772026-05-15T22:50:05.280ZMay 15 22:50:05.254 DEBG destroying link mgtriou_ox_sn_sim1
1782026-05-15T22:50:05.280ZMay 15 22:50:05.254 INFO creating simnet link 'mgtriou_ox_sn_sim1'
1792026-05-15T22:50:05.280ZMay 15 22:50:05.255 INFO creating vnic link 'mgtriou_ox_sn_vnic1'
1802026-05-15T22:50:05.280ZMay 15 22:50:05.262 DEBG link pair created
1812026-05-15T22:50:05.280ZMay 15 22:50:05.262 DEBG destroying link mgtriou_cr2_vn_vnic0
1822026-05-15T22:50:05.280ZMay 15 22:50:05.262 DEBG destroying link mgtriou_cr2_vn_sim0
1832026-05-15T22:50:05.280ZMay 15 22:50:05.262 INFO creating simnet link 'mgtriou_cr2_vn_sim0'
1842026-05-15T22:50:05.306ZMay 15 22:50:05.263 INFO creating vnic link 'mgtriou_cr2_vn_vnic0'
1852026-05-15T22:50:05.306ZMay 15 22:50:05.269 DEBG link pair created
1862026-05-15T22:50:05.306ZMay 15 22:50:05.269 INFO creating external links
1872026-05-15T22:50:05.306ZMay 15 22:50:05.270 DEBG destroying external link mgtriou_ox_vn_vnic2
1882026-05-15T22:50:05.306ZMay 15 22:50:05.270 INFO creating external link mgtriou_ox_vn_vnic2
1892026-05-15T22:50:05.306ZMay 15 22:50:05.271 DEBG external link mgtriou_ox_vn_vnic2@igb0 created
1902026-05-15T22:50:05.306ZMay 15 22:50:05.271 DEBG destroying external link mgtriou_cr1_vn_vnic1
1912026-05-15T22:50:05.306ZMay 15 22:50:05.271 INFO creating external link mgtriou_cr1_vn_vnic1
1922026-05-15T22:50:05.306ZMay 15 22:50:05.273 DEBG external link mgtriou_cr1_vn_vnic1@igb0 created
1932026-05-15T22:50:05.306ZMay 15 22:50:05.273 DEBG destroying external link mgtriou_cr2_vn_vnic1
1942026-05-15T22:50:05.306ZMay 15 22:50:05.273 INFO creating external link mgtriou_cr2_vn_vnic1
1952026-05-15T22:50:05.306ZMay 15 22:50:05.274 DEBG external link mgtriou_cr2_vn_vnic1@igb0 created
1962026-05-15T22:50:05.306ZMay 15 22:50:05.274 INFO creating nodes
1972026-05-15T22:50:05.306ZMay 15 22:50:05.274 INFO ox: launching node
1982026-05-15T22:50:05.306ZMay 15 22:50:05.276 INFO cr1: launching node
1992026-05-15T22:50:05.306ZMay 15 22:50:05.278 INFO cr2: launching node
2002026-05-15T22:50:05.331ZMay 15 22:50:05.291 INFO launched instance ox with pid 857 on port 53073
2012026-05-15T22:50:05.331ZMay 15 22:50:05.291 INFO ox: instance ensure
2022026-05-15T22:50:05.331ZMay 15 22:50:05.292 INFO launched instance cr1 with pid 858 on port 42658
2032026-05-15T22:50:05.332ZMay 15 22:50:05.292 INFO cr1: instance ensure
2042026-05-15T22:50:05.332ZMay 15 22:50:05.292 INFO launched instance cr2 with pid 859 on port 41314
2052026-05-15T22:50:05.332ZMay 15 22:50:05.292 INFO cr2: instance ensure
2062026-05-15T22:50:07.511ZMay 15 22:50:07.495 INFO cr1: instance ensure completed after 0 retries
2072026-05-15T22:50:07.511ZMay 15 22:50:07.495 INFO cr1: instance run
2082026-05-15T22:50:07.536ZMay 15 22:50:07.496 DEBG [sc] cr1: starting
2092026-05-15T22:50:07.536ZMay 15 22:50:07.496 DEBG [sc] cr1: connecting to [::1]:42658
2102026-05-15T22:50:07.536ZMay 15 22:50:07.497 DEBG [sc] cr1 waiting for prompt
2112026-05-15T22:50:07.718ZMay 15 22:50:07.702 INFO ox: instance ensure completed after 0 retries
2122026-05-15T22:50:07.718ZMay 15 22:50:07.702 INFO ox: instance run
2132026-05-15T22:50:07.742ZMay 15 22:50:07.702 DEBG [sc] ox: starting
2142026-05-15T22:50:07.742ZMay 15 22:50:07.702 DEBG [sc] ox: connecting to [::1]:53073
2152026-05-15T22:50:07.742ZMay 15 22:50:07.703 DEBG [sc] ox waiting for prompt
2162026-05-15T22:50:07.742ZMay 15 22:50:07.726 INFO cr2: instance ensure completed after 0 retries
2172026-05-15T22:50:07.742ZMay 15 22:50:07.726 INFO cr2: instance run
2182026-05-15T22:50:07.742ZMay 15 22:50:07.726 DEBG [sc] cr2: starting
2192026-05-15T22:50:07.742ZMay 15 22:50:07.726 DEBG [sc] cr2: connecting to [::1]:41314
2202026-05-15T22:50:07.767ZMay 15 22:50:07.727 DEBG [sc] cr2 waiting for prompt
2212026-05-15T22:50:24.544ZMay 15 22:50:24.528 DEBG [sc] cr1: logging in
2222026-05-15T22:50:24.926ZMay 15 22:50:24.909 INFO cr1: mounting /opt/cargo-bay
2232026-05-15T22:50:24.926ZMay 15 22:50:24.909 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2242026-05-15T22:50:24.950ZMay 15 22:50:24.930 DEBG [sc] cr1: executing command `cd`
2252026-05-15T22:50:24.976ZMay 15 22:50:24.941 INFO cr1: finished mounting /opt/cargo-bay
2262026-05-15T22:50:24.976ZMay 15 22:50:24.941 DEBG [sc] cr1: executing command `hostname cr1`
2272026-05-15T22:50:24.976ZMay 15 22:50:24.953 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
2282026-05-15T22:50:25.001ZMay 15 22:50:24.964 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
2292026-05-15T22:50:25.001ZMay 15 22:50:24.976 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
2302026-05-15T22:50:25.025ZMay 15 22:50:24.985 INFO cr1: logging out
2312026-05-15T22:50:27.055ZMay 15 22:50:27.039 INFO cr1: logged out
2322026-05-15T22:50:28.156ZMay 15 22:50:28.140 DEBG [sc] ox: logging in
2332026-05-15T22:50:28.311ZMay 15 22:50:28.296 INFO ox: mounting /opt/cargo-bay
2342026-05-15T22:50:28.311ZMay 15 22:50:28.296 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2352026-05-15T22:50:29.473ZMay 15 22:50:29.457 DEBG [sc] cr2: logging in
2362026-05-15T22:50:29.524ZMay 15 22:50:29.508 DEBG [sc] ox: executing command `cd`
2372026-05-15T22:50:29.548ZMay 15 22:50:29.519 INFO ox: finished mounting /opt/cargo-bay
2382026-05-15T22:50:29.548ZMay 15 22:50:29.519 DEBG [sc] ox: executing command `hostname ox`
2392026-05-15T22:50:29.548ZMay 15 22:50:29.531 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
2402026-05-15T22:50:29.573ZMay 15 22:50:29.541 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
2412026-05-15T22:50:29.573ZMay 15 22:50:29.552 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
2422026-05-15T22:50:29.597ZMay 15 22:50:29.563 INFO ox: logging out
2432026-05-15T22:50:29.667ZMay 15 22:50:29.651 INFO ox: logged out
2442026-05-15T22:50:29.838ZMay 15 22:50:29.822 INFO cr2: mounting /opt/cargo-bay
2452026-05-15T22:50:29.838ZMay 15 22:50:29.822 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2462026-05-15T22:50:29.862ZMay 15 22:50:29.843 DEBG [sc] cr2: executing command `cd`
2472026-05-15T22:50:29.888ZMay 15 22:50:29.854 INFO cr2: finished mounting /opt/cargo-bay
2482026-05-15T22:50:29.888ZMay 15 22:50:29.854 DEBG [sc] cr2: executing command `hostname cr2`
2492026-05-15T22:50:29.888ZMay 15 22:50:29.866 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
2502026-05-15T22:50:29.912ZMay 15 22:50:29.877 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
2512026-05-15T22:50:29.912ZMay 15 22:50:29.888 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
2522026-05-15T22:50:29.937ZMay 15 22:50:29.898 INFO cr2: logging out
2532026-05-15T22:50:32.927ZMay 15 22:50:32.912 INFO cr2: logged out
2542026-05-15T22:50:32.952ZMay 15 22:50:32.912 DEBG [sc] ox: starting
2552026-05-15T22:50:32.952ZMay 15 22:50:32.912 DEBG [sc] ox: connecting to [::1]:53073
2562026-05-15T22:50:32.952ZMay 15 22:50:32.912 DEBG [sc] ox waiting for prompt
2572026-05-15T22:50:32.952ZMay 15 22:50:32.924 DEBG [sc] ox: logging in
2582026-05-15T22:50:33.027ZMay 15 22:50:33.011 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
2592026-05-15T22:50:39.549ZMay 15 22:50:39.533 DEBG [sc] ox: starting
2602026-05-15T22:50:39.549ZMay 15 22:50:39.533 DEBG [sc] ox: connecting to [::1]:53073
2612026-05-15T22:50:39.575ZMay 15 22:50:39.534 DEBG [sc] ox waiting for prompt
2622026-05-15T22:50:39.575ZMay 15 22:50:39.544 DEBG [sc] ox: logging in
2632026-05-15T22:50:39.637ZMay 15 22:50:39.621 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
2642026-05-15T22:50:39.726ZMay 15 22:50:39.710 DEBG [sc] ox: starting
2652026-05-15T22:50:39.726ZMay 15 22:50:39.710 DEBG [sc] ox: connecting to [::1]:53073
2662026-05-15T22:50:39.750ZMay 15 22:50:39.711 DEBG [sc] ox waiting for prompt
2672026-05-15T22:50:39.750ZMay 15 22:50:39.721 DEBG [sc] ox: logging in
2682026-05-15T22:50:39.813ZMay 15 22:50:39.797 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
2692026-05-15T22:50:39.879ZMay 15 22:50:39.864 INFO cr1: installing frr
2702026-05-15T22:50:39.880ZMay 15 22:50:39.864 INFO waiting for ceos to initialize
2712026-05-15T22:50:39.880ZMay 15 22:50:39.864 INFO ox: setting up npuvm
2722026-05-15T22:50:39.904ZMay 15 22:50:39.864 DEBG [sc] cr2: starting
2732026-05-15T22:50:39.904ZMay 15 22:50:39.864 DEBG [sc] cr2: connecting to [::1]:41314
2742026-05-15T22:50:39.904ZMay 15 22:50:39.864 DEBG [sc] ox: starting
2752026-05-15T22:50:39.904ZMay 15 22:50:39.864 DEBG [sc] ox: connecting to [::1]:53073
2762026-05-15T22:50:39.904ZMay 15 22:50:39.864 DEBG [sc] cr1: starting
2772026-05-15T22:50:39.904ZMay 15 22:50:39.864 DEBG [sc] cr1: connecting to [::1]:42658
2782026-05-15T22:50:39.904ZMay 15 22:50:39.865 DEBG [sc] ox waiting for prompt
2792026-05-15T22:50:39.904ZMay 15 22:50:39.865 DEBG [sc] cr2 waiting for prompt
2802026-05-15T22:50:39.904ZMay 15 22:50:39.865 DEBG [sc] cr1 waiting for prompt
2812026-05-15T22:50:39.904ZMay 15 22:50:39.875 DEBG [sc] ox: logging in
2822026-05-15T22:50:39.904ZMay 15 22:50:39.876 DEBG [sc] cr2: logging in
2832026-05-15T22:50:39.904ZMay 15 22:50:39.876 DEBG [sc] cr1: logging in
2842026-05-15T22:50:39.978ZMay 15 22:50:39.962 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
2852026-05-15T22:50:40.036ZMay 15 22:50:40.020 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
2862026-05-15T22:50:40.260ZMay 15 22:50:40.244 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
2872026-05-15T22:50:42.307ZMay 15 22:50:42.291 INFO cr2: executing eos script show version
2882026-05-15T22:50:42.307ZMay 15 22:50:42.291 DEBG [sc] cr2: starting
2892026-05-15T22:50:42.307ZMay 15 22:50:42.291 DEBG [sc] cr2: connecting to [::1]:41314
2902026-05-15T22:50:42.332ZMay 15 22:50:42.292 DEBG [sc] cr2 waiting for prompt
2912026-05-15T22:50:42.332ZMay 15 22:50:42.302 DEBG [sc] cr2: logging in
2922026-05-15T22:50:42.471ZMay 15 22:50:42.456 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
2932026-05-15T22:50:45.445ZMay 15 22:50:45.430 DEBG [sc] ox: starting
2942026-05-15T22:50:45.445ZMay 15 22:50:45.430 DEBG [sc] ox: connecting to [::1]:53073
2952026-05-15T22:50:45.469ZMay 15 22:50:45.430 DEBG [sc] ox waiting for prompt
2962026-05-15T22:50:45.469ZMay 15 22:50:45.440 DEBG [sc] ox: logging in
2972026-05-15T22:50:45.532ZMay 15 22:50:45.517 DEBG [sc] ox: executing command `chmod +x npuvm`
2982026-05-15T22:50:45.599ZMay 15 22:50:45.584 DEBG [sc] ox: starting
2992026-05-15T22:50:45.599ZMay 15 22:50:45.584 DEBG [sc] ox: connecting to [::1]:53073
3002026-05-15T22:50:45.623ZMay 15 22:50:45.584 DEBG [sc] ox waiting for prompt
3012026-05-15T22:50:45.623ZMay 15 22:50:45.595 DEBG [sc] ox: logging in
3022026-05-15T22:50:45.687ZMay 15 22:50:45.672 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
3032026-05-15T22:50:50.343ZMay 15 22:50:50.328 DEBG [sc] cr2: starting
3042026-05-15T22:50:50.343ZMay 15 22:50:50.328 DEBG [sc] cr2: connecting to [::1]:41314
3052026-05-15T22:50:50.367ZMay 15 22:50:50.329 DEBG [sc] cr2 waiting for prompt
3062026-05-15T22:50:50.367ZMay 15 22:50:50.340 DEBG [sc] cr2: logging in
3072026-05-15T22:50:50.498ZMay 15 22:50:50.483 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3082026-05-15T22:50:52.604ZMay 15 22:50:52.590 INFO cr2: executing eos script show version
3092026-05-15T22:50:52.604ZMay 15 22:50:52.590 DEBG [sc] cr2: starting
3102026-05-15T22:50:52.628ZMay 15 22:50:52.590 DEBG [sc] cr2: connecting to [::1]:41314
3112026-05-15T22:50:52.629ZMay 15 22:50:52.591 DEBG [sc] cr2 waiting for prompt
3122026-05-15T22:50:52.629ZMay 15 22:50:52.601 DEBG [sc] cr2: logging in
3132026-05-15T22:50:52.760ZMay 15 22:50:52.746 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3142026-05-15T22:50:55.086ZMay 15 22:50:55.072 INFO cr2: executing eos script
3152026-05-15T22:50:55.086Z enable
3162026-05-15T22:50:55.086Z configure
3172026-05-15T22:50:55.086Z ipv6 unicast-routing
3182026-05-15T22:50:55.086Z ip routing ipv6 interfaces
3192026-05-15T22:50:55.086Z ip routing
3202026-05-15T22:50:55.086Z ip route 1.2.3.0/24 null0
3212026-05-15T22:50:55.086Z ipv6 route fd99::/64 null0
3222026-05-15T22:50:55.086Z interface et1
3232026-05-15T22:50:55.086Z no switchport
3242026-05-15T22:50:55.086Z ipv6 enable
3252026-05-15T22:50:55.086Z
3262026-05-15T22:50:55.086Z router bgp 45
3272026-05-15T22:50:55.086Z router-id 1.2.3.1
3282026-05-15T22:50:55.086Z no bgp default ipv4-unicast
3292026-05-15T22:50:55.087Z timers bgp 2 6
3302026-05-15T22:50:55.087Z neighbor ebgp peer group
3312026-05-15T22:50:55.087Z neighbor ebgp remote-as 33
3322026-05-15T22:50:55.087Z neighbor interface Et1 peer-group ebgp
3332026-05-15T22:50:55.087Z address-family ipv4
3342026-05-15T22:50:55.087Z neighbor ebgp activate
3352026-05-15T22:50:55.087Z neighbor ebgp next-hop address-family ipv6 originate
3362026-05-15T22:50:55.087Z network 1.2.3.0/24
3372026-05-15T22:50:55.087Z exit
3382026-05-15T22:50:55.087Z address-family ipv6
3392026-05-15T22:50:55.087Z neighbor ebgp activate
3402026-05-15T22:50:55.087Z neighbor ebgp next-hop address-family ipv6 originate
3412026-05-15T22:50:55.087Z network fd99::/64
3422026-05-15T22:50:55.087Z exit
3432026-05-15T22:50:55.087Z exit
3442026-05-15T22:50:55.087Z
3452026-05-15T22:50:55.087ZMay 15 22:50:55.073 DEBG [sc] cr2: starting
3462026-05-15T22:50:55.087ZMay 15 22:50:55.073 DEBG [sc] cr2: connecting to [::1]:41314
3472026-05-15T22:50:55.112ZMay 15 22:50:55.073 DEBG [sc] cr2 waiting for prompt
3482026-05-15T22:50:55.112ZMay 15 22:50:55.083 DEBG [sc] cr2: logging in
3492026-05-15T22:50:55.262ZMay 15 22:50:55.249 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
3502026-05-15T22:50:55.262Z enable
3512026-05-15T22:50:55.262Z configure
3522026-05-15T22:50:55.262Z ipv6 unicast-routing
3532026-05-15T22:50:55.262Z ip routing ipv6 interfaces
3542026-05-15T22:50:55.262Z ip routing
3552026-05-15T22:50:55.262Z ip route 1.2.3.0/24 null0
3562026-05-15T22:50:55.262Z ipv6 route fd99::/64 null0
3572026-05-15T22:50:55.262Z interface et1
3582026-05-15T22:50:55.262Z no switchport
3592026-05-15T22:50:55.262Z ipv6 enable
3602026-05-15T22:50:55.262Z
3612026-05-15T22:50:55.262Z router bgp 45
3622026-05-15T22:50:55.262Z router-id 1.2.3.1
3632026-05-15T22:50:55.262Z no bgp default ipv4-unicast
3642026-05-15T22:50:55.262Z timers bgp 2 6
3652026-05-15T22:50:55.262Z neighbor ebgp peer group
3662026-05-15T22:50:55.262Z neighbor ebgp remote-as 33
3672026-05-15T22:50:55.262Z neighbor interface Et1 peer-group ebgp
3682026-05-15T22:50:55.262Z address-family ipv4
3692026-05-15T22:50:55.263Z neighbor ebgp activate
3702026-05-15T22:50:55.263Z neighbor ebgp next-hop address-family ipv6 originate
3712026-05-15T22:50:55.263Z network 1.2.3.0/24
3722026-05-15T22:50:55.263Z exit
3732026-05-15T22:50:55.263Z address-family ipv6
3742026-05-15T22:50:55.263Z neighbor ebgp activate
3752026-05-15T22:50:55.263Z neighbor ebgp next-hop address-family ipv6 originate
3762026-05-15T22:50:55.263Z network fd99::/64
3772026-05-15T22:50:55.263Z exit
3782026-05-15T22:50:55.263Z exit
3792026-05-15T22:50:55.263Z '`
3802026-05-15T22:51:17.519ZMay 15 22:51:17.507 INFO cr1: enabling frr daemon bgpd
3812026-05-15T22:51:17.519ZMay 15 22:51:17.507 DEBG [sc] cr1: starting
3822026-05-15T22:51:17.519ZMay 15 22:51:17.507 DEBG [sc] cr1: connecting to [::1]:42658
3832026-05-15T22:51:17.544ZMay 15 22:51:17.507 DEBG [sc] cr1 waiting for prompt
3842026-05-15T22:51:17.544ZMay 15 22:51:17.518 DEBG [sc] cr1: logging in
3852026-05-15T22:51:17.663ZMay 15 22:51:17.651 DEBG [sc] cr1: executing command `sed -i 's/bgpd=no/bgpd=yes/g' /etc/frr/daemons`
3862026-05-15T22:51:19.736ZMay 15 22:51:19.724 DEBG [sc] cr1: starting
3872026-05-15T22:51:19.736ZMay 15 22:51:19.724 DEBG [sc] cr1: connecting to [::1]:42658
3882026-05-15T22:51:19.761ZMay 15 22:51:19.724 DEBG [sc] cr1 waiting for prompt
3892026-05-15T22:51:19.761ZMay 15 22:51:19.736 DEBG [sc] cr1: logging in
3902026-05-15T22:51:19.912ZMay 15 22:51:19.900 DEBG [sc] cr1: executing command `systemctl restart frr`
3912026-05-15T22:51:27.526ZMay 15 22:51:27.513 INFO cr1: executing frr script
3922026-05-15T22:51:27.526Z configure
3932026-05-15T22:51:27.526Z ip forwarding
3942026-05-15T22:51:27.526Z ipv6 forwarding
3952026-05-15T22:51:27.526Z ip route 1.2.3.0/24 null0
3962026-05-15T22:51:27.526Z ipv6 route fd99::/64 null0
3972026-05-15T22:51:27.526Z router bgp 44
3982026-05-15T22:51:27.526Z no bgp ebgp-requires-policy
3992026-05-15T22:51:27.526Z timers bgp 2 6
4002026-05-15T22:51:27.526Z neighbor enp0s8 interface remote-as external
4012026-05-15T22:51:27.526Z neighbor enp0s8 timers connect 1
4022026-05-15T22:51:27.526Z address-family ipv4 unicast
4032026-05-15T22:51:27.526Z network 1.2.3.0/24
4042026-05-15T22:51:27.526Z neighbor enp0s8 activate
4052026-05-15T22:51:27.526Z exit-address-family
4062026-05-15T22:51:27.526Z address-family ipv6 unicast
4072026-05-15T22:51:27.526Z network fd99::/64
4082026-05-15T22:51:27.526Z neighbor enp0s8 activate
4092026-05-15T22:51:27.526Z exit-address-family
4102026-05-15T22:51:27.526Z exit
4112026-05-15T22:51:27.526Z
4122026-05-15T22:51:27.551ZMay 15 22:51:27.513 DEBG [sc] cr1: starting
4132026-05-15T22:51:27.551ZMay 15 22:51:27.513 DEBG [sc] cr1: connecting to [::1]:42658
4142026-05-15T22:51:27.551ZMay 15 22:51:27.514 DEBG [sc] cr1 waiting for prompt
4152026-05-15T22:51:27.551ZMay 15 22:51:27.526 DEBG [sc] cr1: logging in
4162026-05-15T22:51:27.649ZMay 15 22:51:27.636 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-15T22:52:34.167ZMay 15 22:52:34.154 DEBG [sc] ox: starting
4182026-05-15T22:52:34.167ZMay 15 22:52:34.154 DEBG [sc] ox: connecting to [::1]:53073
4192026-05-15T22:52:34.191ZMay 15 22:52:34.155 DEBG [sc] ox waiting for prompt
4202026-05-15T22:52:34.192ZMay 15 22:52:34.164 DEBG [sc] ox: logging in
4212026-05-15T22:52:34.255ZMay 15 22:52:34.243 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
4222026-05-15T22:52:34.591ZMay 15 22:52:34.579 DEBG [sc] ox: starting
4232026-05-15T22:52:34.591ZMay 15 22:52:34.579 DEBG [sc] ox: connecting to [::1]:53073
4242026-05-15T22:52:34.616ZMay 15 22:52:34.580 DEBG [sc] ox waiting for prompt
4252026-05-15T22:52:34.616ZMay 15 22:52:34.591 DEBG [sc] ox: logging in
4262026-05-15T22:52:34.680ZMay 15 22:52:34.668 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4272026-05-15T22:52:35.703ZMay 15 22:52:35.691 DEBG [sc] ox: starting
4282026-05-15T22:52:35.703ZMay 15 22:52:35.691 DEBG [sc] ox: connecting to [::1]:53073
4292026-05-15T22:52:35.727ZMay 15 22:52:35.691 DEBG [sc] ox waiting for prompt
4302026-05-15T22:52:35.728ZMay 15 22:52:35.691 DEBG [sc] ox: logging in
4312026-05-15T22:52:35.792ZMay 15 22:52:35.780 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4322026-05-15T22:52:35.858ZMay 15 22:52:35.846 DEBG [sc] ox: starting
4332026-05-15T22:52:35.858ZMay 15 22:52:35.846 DEBG [sc] ox: connecting to [::1]:53073
4342026-05-15T22:52:35.883ZMay 15 22:52:35.847 DEBG [sc] ox waiting for prompt
4352026-05-15T22:52:35.883ZMay 15 22:52:35.857 DEBG [sc] ox: logging in
4362026-05-15T22:52:35.948ZMay 15 22:52:35.935 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
4372026-05-15T22:52:36.014ZMay 15 22:52:36.002 DEBG [sc] ox: starting
4382026-05-15T22:52:36.014ZMay 15 22:52:36.002 DEBG [sc] ox: connecting to [::1]:53073
4392026-05-15T22:52:36.038ZMay 15 22:52:36.002 DEBG [sc] ox waiting for prompt
4402026-05-15T22:52:36.038ZMay 15 22:52:36.013 DEBG [sc] ox: logging in
4412026-05-15T22:52:36.102ZMay 15 22:52:36.090 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
4422026-05-15T22:52:36.170ZMay 15 22:52:36.158 DEBG [sc] ox: starting
4432026-05-15T22:52:36.170ZMay 15 22:52:36.158 DEBG [sc] ox: connecting to [::1]:53073
4442026-05-15T22:52:36.194ZMay 15 22:52:36.158 DEBG [sc] ox waiting for prompt
4452026-05-15T22:52:36.194ZMay 15 22:52:36.168 DEBG [sc] ox: logging in
4462026-05-15T22:52:37.284ZMay 15 22:52:36.247 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
4472026-05-15T22:52:37.309ZMay 15 22:52:36.302 DEBG [sc] ox: starting
4482026-05-15T22:52:37.309ZMay 15 22:52:36.302 DEBG [sc] ox: connecting to [::1]:53073
4492026-05-15T22:52:37.309ZMay 15 22:52:36.302 DEBG [sc] ox waiting for prompt
4502026-05-15T22:52:37.309ZMay 15 22:52:36.313 DEBG [sc] ox: logging in
4512026-05-15T22:52:37.309ZMay 15 22:52:36.390 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
4522026-05-15T22:52:37.309ZMay 15 22:52:36.445 DEBG [sc] ox: starting
4532026-05-15T22:52:37.309ZMay 15 22:52:36.445 DEBG [sc] ox: connecting to [::1]:53073
4542026-05-15T22:52:37.309ZMay 15 22:52:36.446 DEBG [sc] ox waiting for prompt
4552026-05-15T22:52:37.309ZMay 15 22:52:36.457 DEBG [sc] ox: logging in
4562026-05-15T22:52:37.309ZMay 15 22:52:36.535 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
4572026-05-15T22:52:37.309ZMay 15 22:52:36.591 DEBG [sc] ox: starting
4582026-05-15T22:52:37.309ZMay 15 22:52:36.591 DEBG [sc] ox: connecting to [::1]:53073
4592026-05-15T22:52:37.309ZMay 15 22:52:36.591 DEBG [sc] ox waiting for prompt
4602026-05-15T22:52:37.309ZMay 15 22:52:36.602 DEBG [sc] ox: logging in
4612026-05-15T22:52:37.309ZMay 15 22:52:36.679 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
4622026-05-15T22:52:37.309ZMay 15 22:52:36.747 DEBG [sc] ox: starting
4632026-05-15T22:52:37.309ZMay 15 22:52:36.747 DEBG [sc] ox: connecting to [::1]:53073
4642026-05-15T22:52:37.309ZMay 15 22:52:36.748 DEBG [sc] ox waiting for prompt
4652026-05-15T22:52:37.309ZMay 15 22:52:36.758 DEBG [sc] ox: logging in
4662026-05-15T22:52:37.309ZMay 15 22:52:36.835 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
4672026-05-15T22:52:37.309ZMay 15 22:52:36.905 INFO adding BGP router to mgd
4682026-05-15T22:52:39.975ZMay 15 22:52:39.962 INFO cr1: executing frr script show ip bgp json
4692026-05-15T22:52:39.975ZMay 15 22:52:39.962 DEBG [sc] cr1: starting
4702026-05-15T22:52:39.975ZMay 15 22:52:39.962 DEBG [sc] cr1: connecting to [::1]:42658
4712026-05-15T22:52:39.999ZMay 15 22:52:39.963 DEBG [sc] cr1 waiting for prompt
4722026-05-15T22:52:39.999ZMay 15 22:52:39.973 DEBG [sc] cr1: logging in
4732026-05-15T22:52:40.314ZMay 15 22:52:40.302 DEBG [sc] cr1: executing command `vtysh -c 'show ip bgp json'`
4742026-05-15T22:52:42.457ZMay 15 22:52:42.445 INFO cr1: executing frr script show bgp json
4752026-05-15T22:52:42.457ZMay 15 22:52:42.445 DEBG [sc] cr1: starting
4762026-05-15T22:52:42.457ZMay 15 22:52:42.445 DEBG [sc] cr1: connecting to [::1]:42658
4772026-05-15T22:52:42.482ZMay 15 22:52:42.446 DEBG [sc] cr1 waiting for prompt
4782026-05-15T22:52:42.482ZMay 15 22:52:42.456 DEBG [sc] cr1: logging in
4792026-05-15T22:52:42.588ZMay 15 22:52:42.576 DEBG [sc] cr1: executing command `vtysh -c 'show bgp json'`
4802026-05-15T22:52:44.731ZMay 15 22:52:44.719 INFO cr2: executing eos script show ip bgp | json
4812026-05-15T22:52:44.731ZMay 15 22:52:44.719 DEBG [sc] cr2: starting
4822026-05-15T22:52:44.731ZMay 15 22:52:44.719 DEBG [sc] cr2: connecting to [::1]:41314
4832026-05-15T22:52:44.755ZMay 15 22:52:44.720 DEBG [sc] cr2 waiting for prompt
4842026-05-15T22:52:44.755ZMay 15 22:52:44.731 DEBG [sc] cr2: logging in
4852026-05-15T22:52:45.079ZMay 15 22:52:45.067 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ip bgp | json'`
4862026-05-15T22:52:47.470ZMay 15 22:52:47.457 INFO cr2: executing eos script show ipv6 bgp | json
4872026-05-15T22:52:47.470ZMay 15 22:52:47.458 DEBG [sc] cr2: starting
4882026-05-15T22:52:47.470ZMay 15 22:52:47.458 DEBG [sc] cr2: connecting to [::1]:41314
4892026-05-15T22:52:47.495ZMay 15 22:52:47.458 DEBG [sc] cr2 waiting for prompt
4902026-05-15T22:52:47.495ZMay 15 22:52:47.469 DEBG [sc] cr2: logging in
4912026-05-15T22:52:47.613ZMay 15 22:52:47.601 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ipv6 bgp | json'`
4922026-05-15T22:52:50.002ZMay 15 22:52:49.989 INFO trio bgp unnumbered test passed 🎉
4932026-05-15T22:52:50.002ZMay 15 22:52:49.990 INFO destroying runner for deployment mgtriou
4942026-05-15T22:52:50.002ZMay 15 22:52:49.990 INFO destroying deployment mgtriou
4952026-05-15T22:52:50.002ZMay 15 22:52:49.990 INFO destroying nodes
4962026-05-15T22:52:50.109ZMay 15 22:52:50.096 INFO destroying links
4972026-05-15T22:52:50.109ZMay 15 22:52:50.096 INFO destroying link mgtriou_ox_sn_vnic0
4982026-05-15T22:52:50.133ZMay 15 22:52:50.099 INFO destroying link mgtriou_ox_sn_sim0
4992026-05-15T22:52:50.133ZMay 15 22:52:50.101 INFO destroying link mgtriou_cr1_vn_vnic0
5002026-05-15T22:52:51.117ZMay 15 22:52:51.104 INFO destroying link mgtriou_cr1_vn_sim0
5012026-05-15T22:52:51.141ZMay 15 22:52:51.105 INFO destroying link mgtriou_ox_sn_vnic1
5022026-05-15T22:52:51.141ZMay 15 22:52:51.108 INFO destroying link mgtriou_ox_sn_sim1
5032026-05-15T22:52:51.141ZMay 15 22:52:51.109 INFO destroying link mgtriou_cr2_vn_vnic0
5042026-05-15T22:52:51.141ZMay 15 22:52:51.110 INFO destroying link mgtriou_cr2_vn_sim0
5052026-05-15T22:52:51.141ZMay 15 22:52:51.111 INFO destroying external links
5062026-05-15T22:52:51.141ZMay 15 22:52:51.111 INFO destroying external link mgtriou_ox_vn_vnic2
5072026-05-15T22:52:51.141ZMay 15 22:52:51.112 INFO destroying external link mgtriou_cr1_vn_vnic1
5082026-05-15T22:52:51.141ZMay 15 22:52:51.114 INFO destroying external link mgtriou_cr2_vn_vnic1
5092026-05-15T22:52:51.141ZMay 15 22:52:51.115 INFO destroying images
5102026-05-15T22:52:51.588ZMay 15 22:52:51.576 INFO destroying workspace at .falcon
5112026-05-15T22:52:51.612Z+ RUST_LOG=debug
5122026-05-15T22:52:51.612Z+ pfexec ./falcon-lab run trio-bfd-static-routing
5132026-05-15T22:52:51.637ZMay 15 22:52:51.618 DEBG using default route interface igb0
5142026-05-15T22:52:51.637ZMay 15 22:52:51.618 DEBG using default route interface igb0
5152026-05-15T22:52:51.637ZMay 15 22:52:51.618 DEBG using default route interface igb0
5162026-05-15T22:52:51.637ZMay 15 22:52:51.618 INFO launching runner: deployment(mgtriobfd) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
5172026-05-15T22:52:51.637ZMay 15 22:52:51.618 INFO starting preflight for deployment mgtriobfd
5182026-05-15T22:52:52.425ZMay 15 22:52:52.412 INFO creating links
5192026-05-15T22:52:52.425ZMay 15 22:52:52.412 DEBG destroying link mgtriobfd_ox_sn_vnic0
5202026-05-15T22:52:52.425ZMay 15 22:52:52.412 DEBG destroying link mgtriobfd_ox_sn_sim0
5212026-05-15T22:52:52.425ZMay 15 22:52:52.413 INFO creating simnet link 'mgtriobfd_ox_sn_sim0'
5222026-05-15T22:52:52.449ZMay 15 22:52:52.415 INFO creating vnic link 'mgtriobfd_ox_sn_vnic0'
5232026-05-15T22:52:52.449ZMay 15 22:52:52.422 DEBG link pair created
5242026-05-15T22:52:52.450ZMay 15 22:52:52.422 DEBG destroying link mgtriobfd_cr1_vn_vnic0
5252026-05-15T22:52:52.450ZMay 15 22:52:52.422 DEBG destroying link mgtriobfd_cr1_vn_sim0
5262026-05-15T22:52:52.450ZMay 15 22:52:52.422 INFO creating simnet link 'mgtriobfd_cr1_vn_sim0'
5272026-05-15T22:52:52.450ZMay 15 22:52:52.423 INFO creating vnic link 'mgtriobfd_cr1_vn_vnic0'
5282026-05-15T22:52:52.450ZMay 15 22:52:52.429 DEBG link pair created
5292026-05-15T22:52:52.450ZMay 15 22:52:52.429 DEBG destroying link mgtriobfd_ox_sn_vnic1
5302026-05-15T22:52:52.450ZMay 15 22:52:52.429 DEBG destroying link mgtriobfd_ox_sn_sim1
5312026-05-15T22:52:52.450ZMay 15 22:52:52.429 INFO creating simnet link 'mgtriobfd_ox_sn_sim1'
5322026-05-15T22:52:52.450ZMay 15 22:52:52.430 INFO creating vnic link 'mgtriobfd_ox_sn_vnic1'
5332026-05-15T22:52:52.450ZMay 15 22:52:52.437 DEBG link pair created
5342026-05-15T22:52:52.450ZMay 15 22:52:52.437 DEBG destroying link mgtriobfd_cr2_vn_vnic0
5352026-05-15T22:52:52.450ZMay 15 22:52:52.437 DEBG destroying link mgtriobfd_cr2_vn_sim0
5362026-05-15T22:52:52.450ZMay 15 22:52:52.437 INFO creating simnet link 'mgtriobfd_cr2_vn_sim0'
5372026-05-15T22:52:52.474ZMay 15 22:52:52.438 INFO creating vnic link 'mgtriobfd_cr2_vn_vnic0'
5382026-05-15T22:52:52.474ZMay 15 22:52:52.445 DEBG link pair created
5392026-05-15T22:52:52.474ZMay 15 22:52:52.445 INFO creating external links
5402026-05-15T22:52:52.474ZMay 15 22:52:52.445 DEBG destroying external link mgtriobfd_ox_vn_vnic2
5412026-05-15T22:52:52.474ZMay 15 22:52:52.445 INFO creating external link mgtriobfd_ox_vn_vnic2
5422026-05-15T22:52:52.474ZMay 15 22:52:52.446 DEBG external link mgtriobfd_ox_vn_vnic2@igb0 created
5432026-05-15T22:52:52.475ZMay 15 22:52:52.446 DEBG destroying external link mgtriobfd_cr1_vn_vnic1
5442026-05-15T22:52:52.475ZMay 15 22:52:52.446 INFO creating external link mgtriobfd_cr1_vn_vnic1
5452026-05-15T22:52:52.475ZMay 15 22:52:52.447 DEBG external link mgtriobfd_cr1_vn_vnic1@igb0 created
5462026-05-15T22:52:52.475ZMay 15 22:52:52.447 DEBG destroying external link mgtriobfd_cr2_vn_vnic1
5472026-05-15T22:52:52.475ZMay 15 22:52:52.447 INFO creating external link mgtriobfd_cr2_vn_vnic1
5482026-05-15T22:52:52.475ZMay 15 22:52:52.448 DEBG external link mgtriobfd_cr2_vn_vnic1@igb0 created
5492026-05-15T22:52:52.475ZMay 15 22:52:52.449 INFO creating nodes
5502026-05-15T22:52:52.475ZMay 15 22:52:52.449 INFO ox: launching node
5512026-05-15T22:52:52.475ZMay 15 22:52:52.451 INFO cr1: launching node
5522026-05-15T22:52:52.475ZMay 15 22:52:52.453 INFO cr2: launching node
5532026-05-15T22:52:52.499ZMay 15 22:52:52.466 INFO launched instance ox with pid 896 on port 49170
5542026-05-15T22:52:52.499ZMay 15 22:52:52.466 INFO ox: instance ensure
5552026-05-15T22:52:52.499ZMay 15 22:52:52.467 INFO launched instance cr1 with pid 897 on port 42971
5562026-05-15T22:52:52.499ZMay 15 22:52:52.467 INFO cr1: instance ensure
5572026-05-15T22:52:52.499ZMay 15 22:52:52.467 INFO launched instance cr2 with pid 898 on port 48071
5582026-05-15T22:52:52.499ZMay 15 22:52:52.467 INFO cr2: instance ensure
5592026-05-15T22:52:54.637ZMay 15 22:52:54.625 INFO ox: instance ensure completed after 0 retries
5602026-05-15T22:52:54.637ZMay 15 22:52:54.625 INFO ox: instance run
5612026-05-15T22:52:54.662ZMay 15 22:52:54.625 DEBG [sc] ox: starting
5622026-05-15T22:52:54.662ZMay 15 22:52:54.625 DEBG [sc] ox: connecting to [::1]:49170
5632026-05-15T22:52:54.662ZMay 15 22:52:54.626 DEBG [sc] ox waiting for prompt
5642026-05-15T22:52:54.792ZMay 15 22:52:54.779 INFO cr2: instance ensure completed after 0 retries
5652026-05-15T22:52:54.792ZMay 15 22:52:54.779 INFO cr2: instance run
5662026-05-15T22:52:54.816ZMay 15 22:52:54.780 DEBG [sc] cr2: starting
5672026-05-15T22:52:54.816ZMay 15 22:52:54.780 DEBG [sc] cr2: connecting to [::1]:48071
5682026-05-15T22:52:54.816ZMay 15 22:52:54.781 DEBG [sc] cr2 waiting for prompt
5692026-05-15T22:52:54.841ZMay 15 22:52:54.810 INFO cr1: instance ensure completed after 0 retries
5702026-05-15T22:52:54.841ZMay 15 22:52:54.810 INFO cr1: instance run
5712026-05-15T22:52:54.841ZMay 15 22:52:54.810 DEBG [sc] cr1: starting
5722026-05-15T22:52:54.841ZMay 15 22:52:54.810 DEBG [sc] cr1: connecting to [::1]:42971
5732026-05-15T22:52:54.841ZMay 15 22:52:54.811 DEBG [sc] cr1 waiting for prompt
5742026-05-15T22:53:11.897ZMay 15 22:53:11.885 DEBG [sc] cr1: logging in
5752026-05-15T22:53:12.272ZMay 15 22:53:12.259 INFO cr1: mounting /opt/cargo-bay
5762026-05-15T22:53:12.272ZMay 15 22:53:12.259 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5772026-05-15T22:53:12.296ZMay 15 22:53:12.282 DEBG [sc] cr1: executing command `cd`
5782026-05-15T22:53:12.320ZMay 15 22:53:12.293 INFO cr1: finished mounting /opt/cargo-bay
5792026-05-15T22:53:12.320ZMay 15 22:53:12.293 DEBG [sc] cr1: executing command `hostname cr1`
5802026-05-15T22:53:12.320ZMay 15 22:53:12.304 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
5812026-05-15T22:53:12.344ZMay 15 22:53:12.314 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
5822026-05-15T22:53:12.344ZMay 15 22:53:12.325 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
5832026-05-15T22:53:12.369ZMay 15 22:53:12.337 INFO cr1: logging out
5842026-05-15T22:53:14.416ZMay 15 22:53:14.403 INFO cr1: logged out
5852026-05-15T22:53:15.296ZMay 15 22:53:15.284 DEBG [sc] ox: logging in
5862026-05-15T22:53:15.505ZMay 15 22:53:15.493 INFO ox: mounting /opt/cargo-bay
5872026-05-15T22:53:15.505ZMay 15 22:53:15.493 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5882026-05-15T22:53:16.375ZMay 15 22:53:16.363 DEBG [sc] cr2: logging in
5892026-05-15T22:53:16.557ZMay 15 22:53:16.545 DEBG [sc] ox: executing command `cd`
5902026-05-15T22:53:16.581ZMay 15 22:53:16.556 INFO ox: finished mounting /opt/cargo-bay
5912026-05-15T22:53:16.581ZMay 15 22:53:16.556 DEBG [sc] ox: executing command `hostname ox`
5922026-05-15T22:53:16.581ZMay 15 22:53:16.567 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
5932026-05-15T22:53:16.605ZMay 15 22:53:16.577 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
5942026-05-15T22:53:16.606ZMay 15 22:53:16.588 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
5952026-05-15T22:53:16.630ZMay 15 22:53:16.599 INFO ox: logging out
5962026-05-15T22:53:16.678ZMay 15 22:53:16.666 INFO ox: logged out
5972026-05-15T22:53:16.849ZMay 15 22:53:16.837 INFO cr2: mounting /opt/cargo-bay
5982026-05-15T22:53:16.849ZMay 15 22:53:16.837 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5992026-05-15T22:53:16.874ZMay 15 22:53:16.859 DEBG [sc] cr2: executing command `cd`
6002026-05-15T22:53:16.898ZMay 15 22:53:16.871 INFO cr2: finished mounting /opt/cargo-bay
6012026-05-15T22:53:16.898ZMay 15 22:53:16.871 DEBG [sc] cr2: executing command `hostname cr2`
6022026-05-15T22:53:16.898ZMay 15 22:53:16.882 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
6032026-05-15T22:53:16.922ZMay 15 22:53:16.893 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
6042026-05-15T22:53:16.922ZMay 15 22:53:16.904 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
6052026-05-15T22:53:16.946ZMay 15 22:53:16.915 INFO cr2: logging out
6062026-05-15T22:53:19.917ZMay 15 22:53:19.905 INFO cr2: logged out
6072026-05-15T22:53:19.942ZMay 15 22:53:19.905 DEBG [sc] ox: starting
6082026-05-15T22:53:19.942ZMay 15 22:53:19.905 DEBG [sc] ox: connecting to [::1]:49170
6092026-05-15T22:53:19.942ZMay 15 22:53:19.906 DEBG [sc] ox waiting for prompt
6102026-05-15T22:53:19.942ZMay 15 22:53:19.917 DEBG [sc] ox: logging in
6112026-05-15T22:53:20.018ZMay 15 22:53:20.005 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
6122026-05-15T22:53:25.920ZMay 15 22:53:25.908 DEBG [sc] ox: starting
6132026-05-15T22:53:25.920ZMay 15 22:53:25.908 DEBG [sc] ox: connecting to [::1]:49170
6142026-05-15T22:53:25.945ZMay 15 22:53:25.908 DEBG [sc] ox waiting for prompt
6152026-05-15T22:53:25.945ZMay 15 22:53:25.919 DEBG [sc] ox: logging in
6162026-05-15T22:53:26.008ZMay 15 22:53:25.996 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
6172026-05-15T22:53:26.096ZMay 15 22:53:26.084 DEBG [sc] ox: starting
6182026-05-15T22:53:26.096ZMay 15 22:53:26.084 DEBG [sc] ox: connecting to [::1]:49170
6192026-05-15T22:53:26.121ZMay 15 22:53:26.085 DEBG [sc] ox waiting for prompt
6202026-05-15T22:53:26.121ZMay 15 22:53:26.095 DEBG [sc] ox: logging in
6212026-05-15T22:53:26.195ZMay 15 22:53:26.183 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
6222026-05-15T22:53:26.262ZMay 15 22:53:26.250 INFO cr1: installing frr
6232026-05-15T22:53:26.262ZMay 15 22:53:26.250 INFO waiting for ceos to initialize
6242026-05-15T22:53:26.262ZMay 15 22:53:26.250 INFO ox: setting up npuvm
6252026-05-15T22:53:26.286ZMay 15 22:53:26.250 DEBG [sc] cr1: starting
6262026-05-15T22:53:26.286ZMay 15 22:53:26.250 DEBG [sc] cr1: connecting to [::1]:42971
6272026-05-15T22:53:26.286ZMay 15 22:53:26.250 DEBG [sc] cr2: starting
6282026-05-15T22:53:26.286ZMay 15 22:53:26.250 DEBG [sc] cr2: connecting to [::1]:48071
6292026-05-15T22:53:26.286ZMay 15 22:53:26.250 DEBG [sc] ox: starting
6302026-05-15T22:53:26.286ZMay 15 22:53:26.250 DEBG [sc] ox: connecting to [::1]:49170
6312026-05-15T22:53:26.286ZMay 15 22:53:26.250 DEBG [sc] ox waiting for prompt
6322026-05-15T22:53:26.286ZMay 15 22:53:26.250 DEBG [sc] cr2 waiting for prompt
6332026-05-15T22:53:26.286ZMay 15 22:53:26.250 DEBG [sc] cr1 waiting for prompt
6342026-05-15T22:53:26.286ZMay 15 22:53:26.259 DEBG [sc] ox: logging in
6352026-05-15T22:53:26.286ZMay 15 22:53:26.261 DEBG [sc] cr1: logging in
6362026-05-15T22:53:26.286ZMay 15 22:53:26.262 DEBG [sc] cr2: logging in
6372026-05-15T22:53:26.350ZMay 15 22:53:26.337 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
6382026-05-15T22:53:26.406ZMay 15 22:53:26.394 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6392026-05-15T22:53:26.631ZMay 15 22:53:26.619 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
6402026-05-15T22:53:28.656ZMay 15 22:53:28.643 INFO cr2: executing eos script show version
6412026-05-15T22:53:28.656ZMay 15 22:53:28.644 DEBG [sc] cr2: starting
6422026-05-15T22:53:28.656ZMay 15 22:53:28.644 DEBG [sc] cr2: connecting to [::1]:48071
6432026-05-15T22:53:28.707ZMay 15 22:53:28.644 DEBG [sc] cr2 waiting for prompt
6442026-05-15T22:53:28.732ZMay 15 22:53:28.653 DEBG [sc] cr2: logging in
6452026-05-15T22:53:28.801ZMay 15 22:53:28.787 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6462026-05-15T22:53:33.711ZMay 15 22:53:33.664 DEBG [sc] ox: starting
6472026-05-15T22:53:33.711ZMay 15 22:53:33.664 DEBG [sc] ox: connecting to [::1]:49170
6482026-05-15T22:53:33.711ZMay 15 22:53:33.664 DEBG [sc] ox waiting for prompt
6492026-05-15T22:53:33.711ZMay 15 22:53:33.675 DEBG [sc] ox: logging in
6502026-05-15T22:53:33.763ZMay 15 22:53:33.751 DEBG [sc] ox: executing command `chmod +x npuvm`
6512026-05-15T22:53:33.830ZMay 15 22:53:33.818 DEBG [sc] ox: starting
6522026-05-15T22:53:33.830ZMay 15 22:53:33.818 DEBG [sc] ox: connecting to [::1]:49170
6532026-05-15T22:53:33.854ZMay 15 22:53:33.818 DEBG [sc] ox waiting for prompt
6542026-05-15T22:53:33.854ZMay 15 22:53:33.828 DEBG [sc] ox: logging in
6552026-05-15T22:53:33.917ZMay 15 22:53:33.905 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
6562026-05-15T22:53:35.775ZMay 15 22:53:35.763 INFO cr1: enabling frr daemon bfdd
6572026-05-15T22:53:35.775ZMay 15 22:53:35.763 DEBG [sc] cr1: starting
6582026-05-15T22:53:35.775ZMay 15 22:53:35.763 DEBG [sc] cr1: connecting to [::1]:42971
6592026-05-15T22:53:35.799ZMay 15 22:53:35.763 DEBG [sc] cr1 waiting for prompt
6602026-05-15T22:53:35.799ZMay 15 22:53:35.773 DEBG [sc] cr1: logging in
6612026-05-15T22:53:35.941ZMay 15 22:53:35.929 DEBG [sc] cr1: executing command `sed -i 's/bfdd=no/bfdd=yes/g' /etc/frr/daemons`
6622026-05-15T22:53:37.146ZMay 15 22:53:37.133 DEBG [sc] cr2: starting
6632026-05-15T22:53:37.146ZMay 15 22:53:37.133 DEBG [sc] cr2: connecting to [::1]:48071
6642026-05-15T22:53:37.175ZMay 15 22:53:37.133 DEBG [sc] cr2 waiting for prompt
6652026-05-15T22:53:37.175ZMay 15 22:53:37.144 DEBG [sc] cr2: logging in
6662026-05-15T22:53:37.310ZMay 15 22:53:37.298 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6672026-05-15T22:53:38.029ZMay 15 22:53:38.016 DEBG [sc] cr1: starting
6682026-05-15T22:53:38.029ZMay 15 22:53:38.016 DEBG [sc] cr1: connecting to [::1]:42971
6692026-05-15T22:53:38.053ZMay 15 22:53:38.017 DEBG [sc] cr1 waiting for prompt
6702026-05-15T22:53:38.053ZMay 15 22:53:38.027 DEBG [sc] cr1: logging in
6712026-05-15T22:53:38.184ZMay 15 22:53:38.171 DEBG [sc] cr1: executing command `systemctl restart frr`
6722026-05-15T22:53:39.441ZMay 15 22:53:39.429 INFO cr2: executing eos script show version
6732026-05-15T22:53:39.441ZMay 15 22:53:39.429 DEBG [sc] cr2: starting
6742026-05-15T22:53:39.441ZMay 15 22:53:39.429 DEBG [sc] cr2: connecting to [::1]:48071
6752026-05-15T22:53:39.468ZMay 15 22:53:39.429 DEBG [sc] cr2 waiting for prompt
6762026-05-15T22:53:39.468ZMay 15 22:53:39.439 DEBG [sc] cr2: logging in
6772026-05-15T22:53:39.595ZMay 15 22:53:39.582 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6782026-05-15T22:53:41.949ZMay 15 22:53:41.936 INFO cr2: executing eos script
6792026-05-15T22:53:41.949Z enable
6802026-05-15T22:53:41.949Z configure
6812026-05-15T22:53:41.949Z ip routing
6822026-05-15T22:53:41.949Z ipv6 unicast-routing
6832026-05-15T22:53:41.949Z interface Ethernet1
6842026-05-15T22:53:41.949Z no switchport
6852026-05-15T22:53:41.949Z ip address 10.0.1.2/24
6862026-05-15T22:53:41.949Z ipv6 enable
6872026-05-15T22:53:41.949Z ipv6 address fd00:2::2/64
6882026-05-15T22:53:41.949Z bfd interval 300 min-rx 300 multiplier 3
6892026-05-15T22:53:41.949Z exit
6902026-05-15T22:53:41.950Z ip route 100.64.0.0/24 10.0.1.1 track bfd
6912026-05-15T22:53:41.950Z ipv6 route 3fff::/64 fd00:2::1 track bfd
6922026-05-15T22:53:41.950Z exit
6932026-05-15T22:53:41.950Z
6942026-05-15T22:53:41.950ZMay 15 22:53:41.937 DEBG [sc] cr2: starting
6952026-05-15T22:53:41.950ZMay 15 22:53:41.937 DEBG [sc] cr2: connecting to [::1]:48071
6962026-05-15T22:53:41.974ZMay 15 22:53:41.937 DEBG [sc] cr2 waiting for prompt
6972026-05-15T22:53:41.974ZMay 15 22:53:41.947 DEBG [sc] cr2: logging in
6982026-05-15T22:53:42.126ZMay 15 22:53:42.114 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
6992026-05-15T22:53:42.126Z enable
7002026-05-15T22:53:42.126Z configure
7012026-05-15T22:53:42.126Z ip routing
7022026-05-15T22:53:42.126Z ipv6 unicast-routing
7032026-05-15T22:53:42.126Z interface Ethernet1
7042026-05-15T22:53:42.127Z no switchport
7052026-05-15T22:53:42.127Z ip address 10.0.1.2/24
7062026-05-15T22:53:42.127Z ipv6 enable
7072026-05-15T22:53:42.127Z ipv6 address fd00:2::2/64
7082026-05-15T22:53:42.127Z bfd interval 300 min-rx 300 multiplier 3
7092026-05-15T22:53:42.127Z exit
7102026-05-15T22:53:42.127Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7112026-05-15T22:53:42.127Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7122026-05-15T22:53:42.127Z exit
7132026-05-15T22:53:42.127Z '`
7142026-05-15T22:53:45.754ZMay 15 22:53:45.741 INFO cr1: executing frr script
7152026-05-15T22:53:45.754Z configure
7162026-05-15T22:53:45.754Z interface enp0s8
7172026-05-15T22:53:45.754Z ip address 10.0.0.2/24
7182026-05-15T22:53:45.754Z ipv6 address fd00:1::2/64
7192026-05-15T22:53:45.754Z no shutdown
7202026-05-15T22:53:45.754Z exit
7212026-05-15T22:53:45.754Z bfd
7222026-05-15T22:53:45.754Z peer 10.0.0.1 local-address 10.0.0.2
7232026-05-15T22:53:45.754Z detect-multiplier 3
7242026-05-15T22:53:45.754Z receive-interval 300
7252026-05-15T22:53:45.754Z transmit-interval 300
7262026-05-15T22:53:45.754Z no shutdown
7272026-05-15T22:53:45.754Z exit
7282026-05-15T22:53:45.754Z peer fd00:1::1 local-address fd00:1::2
7292026-05-15T22:53:45.754Z detect-multiplier 3
7302026-05-15T22:53:45.754Z receive-interval 300
7312026-05-15T22:53:45.754Z transmit-interval 300
7322026-05-15T22:53:45.754Z no shutdown
7332026-05-15T22:53:45.754Z exit
7342026-05-15T22:53:45.754Z exit
7352026-05-15T22:53:45.754Z
7362026-05-15T22:53:45.754ZMay 15 22:53:45.741 DEBG [sc] cr1: starting
7372026-05-15T22:53:45.754ZMay 15 22:53:45.741 DEBG [sc] cr1: connecting to [::1]:42971
7382026-05-15T22:53:45.779ZMay 15 22:53:45.742 DEBG [sc] cr1 waiting for prompt
7392026-05-15T22:53:45.779ZMay 15 22:53:45.753 DEBG [sc] cr1: logging in
7402026-05-15T22:53:45.897ZMay 15 22:53:45.884 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 ' '`
7412026-05-15T22:55:22.859ZMay 15 22:55:22.846 DEBG [sc] ox: starting
7422026-05-15T22:55:22.859ZMay 15 22:55:22.846 DEBG [sc] ox: connecting to [::1]:49170
7432026-05-15T22:55:22.883ZMay 15 22:55:22.846 DEBG [sc] ox waiting for prompt
7442026-05-15T22:55:22.883ZMay 15 22:55:22.856 DEBG [sc] ox: logging in
7452026-05-15T22:55:22.957ZMay 15 22:55:22.945 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
7462026-05-15T22:55:23.311ZMay 15 22:55:23.298 DEBG [sc] ox: starting
7472026-05-15T22:55:23.311ZMay 15 22:55:23.298 DEBG [sc] ox: connecting to [::1]:49170
7482026-05-15T22:55:23.335ZMay 15 22:55:23.299 DEBG [sc] ox waiting for prompt
7492026-05-15T22:55:23.335ZMay 15 22:55:23.310 DEBG [sc] ox: logging in
7502026-05-15T22:55:23.401ZMay 15 22:55:23.388 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7512026-05-15T22:55:23.456ZMay 15 22:55:23.444 DEBG [sc] ox: starting
7522026-05-15T22:55:23.456ZMay 15 22:55:23.444 DEBG [sc] ox: connecting to [::1]:49170
7532026-05-15T22:55:23.481ZMay 15 22:55:23.445 DEBG [sc] ox waiting for prompt
7542026-05-15T22:55:23.481ZMay 15 22:55:23.455 DEBG [sc] ox: logging in
7552026-05-15T22:55:23.545ZMay 15 22:55:23.533 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7562026-05-15T22:55:24.570ZMay 15 22:55:24.557 DEBG [sc] ox: starting
7572026-05-15T22:55:24.570ZMay 15 22:55:24.557 DEBG [sc] ox: connecting to [::1]:49170
7582026-05-15T22:55:24.594ZMay 15 22:55:24.558 DEBG [sc] ox waiting for prompt
7592026-05-15T22:55:24.594ZMay 15 22:55:24.558 DEBG [sc] ox: logging in
7602026-05-15T22:55:24.647ZMay 15 22:55:24.635 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7612026-05-15T22:55:25.670ZMay 15 22:55:25.658 DEBG [sc] ox: starting
7622026-05-15T22:55:25.670ZMay 15 22:55:25.658 DEBG [sc] ox: connecting to [::1]:49170
7632026-05-15T22:55:25.695ZMay 15 22:55:25.659 DEBG [sc] ox waiting for prompt
7642026-05-15T22:55:25.695ZMay 15 22:55:25.659 DEBG [sc] ox: logging in
7652026-05-15T22:55:25.748ZMay 15 22:55:25.736 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7662026-05-15T22:55:26.135ZMay 15 22:55:26.122 DEBG [sc] ox: starting
7672026-05-15T22:55:26.135ZMay 15 22:55:26.122 DEBG [sc] ox: connecting to [::1]:49170
7682026-05-15T22:55:26.159ZMay 15 22:55:26.123 DEBG [sc] ox waiting for prompt
7692026-05-15T22:55:26.159ZMay 15 22:55:26.134 DEBG [sc] ox: logging in
7702026-05-15T22:55:26.224ZMay 15 22:55:26.211 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
7712026-05-15T22:55:26.278ZMay 15 22:55:26.266 DEBG [sc] ox: starting
7722026-05-15T22:55:26.279ZMay 15 22:55:26.266 DEBG [sc] ox: connecting to [::1]:49170
7732026-05-15T22:55:26.303ZMay 15 22:55:26.267 DEBG [sc] ox waiting for prompt
7742026-05-15T22:55:26.303ZMay 15 22:55:26.277 DEBG [sc] ox: logging in
7752026-05-15T22:55:26.368ZMay 15 22:55:26.355 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
7762026-05-15T22:55:26.423ZMay 15 22:55:26.410 DEBG [sc] ox: starting
7772026-05-15T22:55:26.423ZMay 15 22:55:26.410 DEBG [sc] ox: connecting to [::1]:49170
7782026-05-15T22:55:26.447ZMay 15 22:55:26.411 DEBG [sc] ox waiting for prompt
7792026-05-15T22:55:26.447ZMay 15 22:55:26.422 DEBG [sc] ox: logging in
7802026-05-15T22:55:26.511ZMay 15 22:55:26.499 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.0.1/24 tfportqsfp0_0/v4`
7812026-05-15T22:55:27.176ZMay 15 22:55:27.164 DEBG [sc] ox: starting
7822026-05-15T22:55:27.176ZMay 15 22:55:27.164 DEBG [sc] ox: connecting to [::1]:49170
7832026-05-15T22:55:27.201ZMay 15 22:55:27.165 DEBG [sc] ox waiting for prompt
7842026-05-15T22:55:27.201ZMay 15 22:55:27.175 DEBG [sc] ox: logging in
7852026-05-15T22:55:27.266ZMay 15 22:55:27.253 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v4 -p -o addr`
7862026-05-15T22:55:27.320ZMay 15 22:55:27.308 DEBG [sc] ox: starting
7872026-05-15T22:55:27.320ZMay 15 22:55:27.308 DEBG [sc] ox: connecting to [::1]:49170
7882026-05-15T22:55:27.344ZMay 15 22:55:27.309 DEBG [sc] ox waiting for prompt
7892026-05-15T22:55:27.345ZMay 15 22:55:27.319 DEBG [sc] ox: logging in
7902026-05-15T22:55:27.409ZMay 15 22:55:27.397 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:1::1/64 tfportqsfp0_0/v6`
7912026-05-15T22:55:27.922ZMay 15 22:55:27.909 DEBG [sc] ox: starting
7922026-05-15T22:55:27.922ZMay 15 22:55:27.909 DEBG [sc] ox: connecting to [::1]:49170
7932026-05-15T22:55:27.946ZMay 15 22:55:27.910 DEBG [sc] ox waiting for prompt
7942026-05-15T22:55:27.946ZMay 15 22:55:27.920 DEBG [sc] ox: logging in
7952026-05-15T22:55:28.010ZMay 15 22:55:27.998 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v6 -p -o addr`
7962026-05-15T22:55:28.066ZMay 15 22:55:28.054 DEBG [sc] ox: starting
7972026-05-15T22:55:28.066ZMay 15 22:55:28.054 DEBG [sc] ox: connecting to [::1]:49170
7982026-05-15T22:55:28.090ZMay 15 22:55:28.054 DEBG [sc] ox waiting for prompt
7992026-05-15T22:55:28.090ZMay 15 22:55:28.065 DEBG [sc] ox: logging in
8002026-05-15T22:55:28.155ZMay 15 22:55:28.142 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
8012026-05-15T22:55:28.210ZMay 15 22:55:28.197 DEBG [sc] ox: starting
8022026-05-15T22:55:28.210ZMay 15 22:55:28.197 DEBG [sc] ox: connecting to [::1]:49170
8032026-05-15T22:55:28.234ZMay 15 22:55:28.198 DEBG [sc] ox waiting for prompt
8042026-05-15T22:55:28.234ZMay 15 22:55:28.208 DEBG [sc] ox: logging in
8052026-05-15T22:55:28.297ZMay 15 22:55:28.285 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
8062026-05-15T22:55:28.353ZMay 15 22:55:28.340 DEBG [sc] ox: starting
8072026-05-15T22:55:28.353ZMay 15 22:55:28.340 DEBG [sc] ox: connecting to [::1]:49170
8082026-05-15T22:55:28.377ZMay 15 22:55:28.341 DEBG [sc] ox waiting for prompt
8092026-05-15T22:55:28.377ZMay 15 22:55:28.351 DEBG [sc] ox: logging in
8102026-05-15T22:55:28.441ZMay 15 22:55:28.428 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.1.1/24 tfportqsfp1_0/v4`
8112026-05-15T22:55:29.011ZMay 15 22:55:28.999 DEBG [sc] ox: starting
8122026-05-15T22:55:29.012ZMay 15 22:55:28.999 DEBG [sc] ox: connecting to [::1]:49170
8132026-05-15T22:55:29.036ZMay 15 22:55:28.999 DEBG [sc] ox waiting for prompt
8142026-05-15T22:55:29.036ZMay 15 22:55:29.009 DEBG [sc] ox: logging in
8152026-05-15T22:55:29.100ZMay 15 22:55:29.087 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v4 -p -o addr`
8162026-05-15T22:55:29.155ZMay 15 22:55:29.142 DEBG [sc] ox: starting
8172026-05-15T22:55:29.155ZMay 15 22:55:29.142 DEBG [sc] ox: connecting to [::1]:49170
8182026-05-15T22:55:29.179ZMay 15 22:55:29.143 DEBG [sc] ox waiting for prompt
8192026-05-15T22:55:29.179ZMay 15 22:55:29.153 DEBG [sc] ox: logging in
8202026-05-15T22:55:29.243ZMay 15 22:55:29.230 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:2::1/64 tfportqsfp1_0/v6`
8212026-05-15T22:55:29.455ZMay 15 22:55:29.442 DEBG [sc] ox: starting
8222026-05-15T22:55:29.455ZMay 15 22:55:29.442 DEBG [sc] ox: connecting to [::1]:49170
8232026-05-15T22:55:29.479ZMay 15 22:55:29.443 DEBG [sc] ox waiting for prompt
8242026-05-15T22:55:29.479ZMay 15 22:55:29.453 DEBG [sc] ox: logging in
8252026-05-15T22:55:29.544ZMay 15 22:55:29.531 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v6 -p -o addr`
8262026-05-15T22:55:29.610ZMay 15 22:55:29.597 DEBG [sc] ox: starting
8272026-05-15T22:55:29.610ZMay 15 22:55:29.597 DEBG [sc] ox: connecting to [::1]:49170
8282026-05-15T22:55:29.634ZMay 15 22:55:29.598 DEBG [sc] ox waiting for prompt
8292026-05-15T22:55:29.634ZMay 15 22:55:29.608 DEBG [sc] ox: logging in
8302026-05-15T22:55:29.698ZMay 15 22:55:29.685 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
8312026-05-15T22:55:29.753ZMay 15 22:55:29.740 DEBG [sc] ox: starting
8322026-05-15T22:55:29.753ZMay 15 22:55:29.740 DEBG [sc] ox: connecting to [::1]:49170
8332026-05-15T22:55:29.777ZMay 15 22:55:29.741 DEBG [sc] ox waiting for prompt
8342026-05-15T22:55:29.777ZMay 15 22:55:29.751 DEBG [sc] ox: logging in
8352026-05-15T22:55:29.852ZMay 15 22:55:29.839 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
8362026-05-15T22:55:29.922ZMay 15 22:55:29.909 INFO installing static v4 route 192.168.100.0/24
8372026-05-15T22:55:29.946ZMay 15 22:55:29.910 INFO installing static v6 route fd01::/64
8382026-05-15T22:55:29.946ZMay 15 22:55:29.911 INFO adding BFD peers for cr1 and cr2 (dual-stack)
8392026-05-15T22:55:29.946ZMay 15 22:55:29.914 INFO phase 1: both peers up
8402026-05-15T22:55:30.930ZMay 15 22:55:30.918 INFO cr1: executing frr script show bfd peers json
8412026-05-15T22:55:30.954ZMay 15 22:55:30.918 DEBG [sc] cr1: starting
8422026-05-15T22:55:30.954ZMay 15 22:55:30.918 DEBG [sc] cr1: connecting to [::1]:42971
8432026-05-15T22:55:30.954ZMay 15 22:55:30.919 DEBG [sc] cr1 waiting for prompt
8442026-05-15T22:55:30.954ZMay 15 22:55:30.929 DEBG [sc] cr1: logging in
8452026-05-15T22:55:31.309ZMay 15 22:55:31.297 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8462026-05-15T22:55:33.452ZMay 15 22:55:33.439 INFO cr1: executing frr script show bfd peers json
8472026-05-15T22:55:33.452ZMay 15 22:55:33.439 DEBG [sc] cr1: starting
8482026-05-15T22:55:33.452ZMay 15 22:55:33.439 DEBG [sc] cr1: connecting to [::1]:42971
8492026-05-15T22:55:33.476ZMay 15 22:55:33.440 DEBG [sc] cr1 waiting for prompt
8502026-05-15T22:55:33.476ZMay 15 22:55:33.450 DEBG [sc] cr1: logging in
8512026-05-15T22:55:33.583ZMay 15 22:55:33.571 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8522026-05-15T22:55:35.723ZMay 15 22:55:35.710 INFO cr2: executing eos script show bfd peers | json
8532026-05-15T22:55:35.723ZMay 15 22:55:35.710 DEBG [sc] cr2: starting
8542026-05-15T22:55:35.723ZMay 15 22:55:35.710 DEBG [sc] cr2: connecting to [::1]:48071
8552026-05-15T22:55:35.747ZMay 15 22:55:35.711 DEBG [sc] cr2 waiting for prompt
8562026-05-15T22:55:35.747ZMay 15 22:55:35.722 DEBG [sc] cr2: logging in
8572026-05-15T22:55:36.066ZMay 15 22:55:36.052 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8582026-05-15T22:55:38.400ZMay 15 22:55:38.388 INFO cr2: executing eos script show bfd peers | json
8592026-05-15T22:55:38.401ZMay 15 22:55:38.388 DEBG [sc] cr2: starting
8602026-05-15T22:55:38.401ZMay 15 22:55:38.388 DEBG [sc] cr2: connecting to [::1]:48071
8612026-05-15T22:55:38.425ZMay 15 22:55:38.389 DEBG [sc] cr2 waiting for prompt
8622026-05-15T22:55:38.425ZMay 15 22:55:38.399 DEBG [sc] cr2: logging in
8632026-05-15T22:55:38.542ZMay 15 22:55:38.530 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8642026-05-15T22:55:40.903ZMay 15 22:55:40.891 INFO phase 2: pause bfdd on cr1
8652026-05-15T22:55:40.903ZMay 15 22:55:40.891 INFO cr1: pausing frr bfdd
8662026-05-15T22:55:40.903ZMay 15 22:55:40.891 DEBG [sc] cr1: starting
8672026-05-15T22:55:40.903ZMay 15 22:55:40.891 DEBG [sc] cr1: connecting to [::1]:42971
8682026-05-15T22:55:40.927ZMay 15 22:55:40.892 DEBG [sc] cr1 waiting for prompt
8692026-05-15T22:55:40.927ZMay 15 22:55:40.902 DEBG [sc] cr1: logging in
8702026-05-15T22:55:41.058ZMay 15 22:55:41.046 DEBG [sc] cr1: executing command `pkill -STOP bfdd`
8712026-05-15T22:55:43.150ZMay 15 22:55:43.137 INFO cr2: executing eos script show bfd peers | json
8722026-05-15T22:55:43.150ZMay 15 22:55:43.137 DEBG [sc] cr2: starting
8732026-05-15T22:55:43.150ZMay 15 22:55:43.137 DEBG [sc] cr2: connecting to [::1]:48071
8742026-05-15T22:55:43.174ZMay 15 22:55:43.138 DEBG [sc] cr2 waiting for prompt
8752026-05-15T22:55:43.174ZMay 15 22:55:43.149 DEBG [sc] cr2: logging in
8762026-05-15T22:55:43.295ZMay 15 22:55:43.283 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8772026-05-15T22:55:45.633ZMay 15 22:55:45.620 INFO cr2: executing eos script show bfd peers | json
8782026-05-15T22:55:45.657ZMay 15 22:55:45.620 DEBG [sc] cr2: starting
8792026-05-15T22:55:45.657ZMay 15 22:55:45.620 DEBG [sc] cr2: connecting to [::1]:48071
8802026-05-15T22:55:45.657ZMay 15 22:55:45.621 DEBG [sc] cr2 waiting for prompt
8812026-05-15T22:55:45.657ZMay 15 22:55:45.630 DEBG [sc] cr2: logging in
8822026-05-15T22:55:45.786ZMay 15 22:55:45.774 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8832026-05-15T22:55:48.114ZMay 15 22:55:48.102 INFO phase 3: pause ceos on cr2
8842026-05-15T22:55:48.115ZMay 15 22:55:48.102 INFO cr2: pausing ceos
8852026-05-15T22:55:48.115ZMay 15 22:55:48.102 DEBG [sc] cr2: starting
8862026-05-15T22:55:48.115ZMay 15 22:55:48.102 DEBG [sc] cr2: connecting to [::1]:48071
8872026-05-15T22:55:48.139ZMay 15 22:55:48.102 DEBG [sc] cr2 waiting for prompt
8882026-05-15T22:55:48.139ZMay 15 22:55:48.112 DEBG [sc] cr2: logging in
8892026-05-15T22:55:48.278ZMay 15 22:55:48.266 DEBG [sc] cr2: executing command `docker pause ceos`
8902026-05-15T22:55:50.388ZMay 15 22:55:50.375 INFO phase 4: resume bfdd on cr1
8912026-05-15T22:55:50.388ZMay 15 22:55:50.375 INFO cr1: resuming frr bfdd
8922026-05-15T22:55:50.388ZMay 15 22:55:50.375 DEBG [sc] cr1: starting
8932026-05-15T22:55:50.388ZMay 15 22:55:50.375 DEBG [sc] cr1: connecting to [::1]:42971
8942026-05-15T22:55:50.412ZMay 15 22:55:50.376 DEBG [sc] cr1 waiting for prompt
8952026-05-15T22:55:50.412ZMay 15 22:55:50.387 DEBG [sc] cr1: logging in
8962026-05-15T22:55:50.521ZMay 15 22:55:50.509 DEBG [sc] cr1: executing command `pkill -CONT bfdd`
8972026-05-15T22:55:52.601ZMay 15 22:55:52.588 INFO cr1: executing frr script show bfd peers json
8982026-05-15T22:55:52.601ZMay 15 22:55:52.588 DEBG [sc] cr1: starting
8992026-05-15T22:55:52.601ZMay 15 22:55:52.588 DEBG [sc] cr1: connecting to [::1]:42971
9002026-05-15T22:55:52.625ZMay 15 22:55:52.589 DEBG [sc] cr1 waiting for prompt
9012026-05-15T22:55:52.625ZMay 15 22:55:52.597 DEBG [sc] cr1: logging in
9022026-05-15T22:55:52.731ZMay 15 22:55:52.719 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9032026-05-15T22:55:54.870ZMay 15 22:55:54.858 INFO cr1: executing frr script show bfd peers json
9042026-05-15T22:55:54.870ZMay 15 22:55:54.858 DEBG [sc] cr1: starting
9052026-05-15T22:55:54.870ZMay 15 22:55:54.858 DEBG [sc] cr1: connecting to [::1]:42971
9062026-05-15T22:55:54.894ZMay 15 22:55:54.858 DEBG [sc] cr1 waiting for prompt
9072026-05-15T22:55:54.894ZMay 15 22:55:54.869 DEBG [sc] cr1: logging in
9082026-05-15T22:55:55.014ZMay 15 22:55:55.001 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9092026-05-15T22:55:57.157ZMay 15 22:55:57.144 INFO phase 5: unpause ceos on cr2
9102026-05-15T22:55:57.157ZMay 15 22:55:57.144 INFO cr2: unpausing ceos
9112026-05-15T22:55:57.157ZMay 15 22:55:57.144 DEBG [sc] cr2: starting
9122026-05-15T22:55:57.157ZMay 15 22:55:57.144 DEBG [sc] cr2: connecting to [::1]:48071
9132026-05-15T22:55:57.181ZMay 15 22:55:57.145 DEBG [sc] cr2 waiting for prompt
9142026-05-15T22:55:57.181ZMay 15 22:55:57.156 DEBG [sc] cr2: logging in
9152026-05-15T22:55:57.312ZMay 15 22:55:57.299 DEBG [sc] cr2: executing command `docker unpause ceos`
9162026-05-15T22:55:59.416ZMay 15 22:55:59.403 INFO cr1: executing frr script show bfd peers json
9172026-05-15T22:55:59.416ZMay 15 22:55:59.403 DEBG [sc] cr1: starting
9182026-05-15T22:55:59.416ZMay 15 22:55:59.403 DEBG [sc] cr1: connecting to [::1]:42971
9192026-05-15T22:55:59.441ZMay 15 22:55:59.404 DEBG [sc] cr1 waiting for prompt
9202026-05-15T22:55:59.441ZMay 15 22:55:59.415 DEBG [sc] cr1: logging in
9212026-05-15T22:55:59.559ZMay 15 22:55:59.547 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9222026-05-15T22:56:01.690ZMay 15 22:56:01.677 INFO cr1: executing frr script show bfd peers json
9232026-05-15T22:56:01.690ZMay 15 22:56:01.677 DEBG [sc] cr1: starting
9242026-05-15T22:56:01.690ZMay 15 22:56:01.677 DEBG [sc] cr1: connecting to [::1]:42971
9252026-05-15T22:56:01.714ZMay 15 22:56:01.678 DEBG [sc] cr1 waiting for prompt
9262026-05-15T22:56:01.714ZMay 15 22:56:01.688 DEBG [sc] cr1: logging in
9272026-05-15T22:56:01.833ZMay 15 22:56:01.821 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9282026-05-15T22:56:03.974ZMay 15 22:56:03.962 INFO cr2: executing eos script show bfd peers | json
9292026-05-15T22:56:03.974ZMay 15 22:56:03.962 DEBG [sc] cr2: starting
9302026-05-15T22:56:03.974ZMay 15 22:56:03.962 DEBG [sc] cr2: connecting to [::1]:48071
9312026-05-15T22:56:03.998ZMay 15 22:56:03.963 DEBG [sc] cr2 waiting for prompt
9322026-05-15T22:56:03.998ZMay 15 22:56:03.973 DEBG [sc] cr2: logging in
9332026-05-15T22:56:04.129ZMay 15 22:56:04.116 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9342026-05-15T22:56:06.446ZMay 15 22:56:06.434 INFO cr2: executing eos script show bfd peers | json
9352026-05-15T22:56:06.446ZMay 15 22:56:06.434 DEBG [sc] cr2: starting
9362026-05-15T22:56:06.446ZMay 15 22:56:06.434 DEBG [sc] cr2: connecting to [::1]:48071
9372026-05-15T22:56:06.470ZMay 15 22:56:06.435 DEBG [sc] cr2 waiting for prompt
9382026-05-15T22:56:06.470ZMay 15 22:56:06.444 DEBG [sc] cr2: logging in
9392026-05-15T22:56:06.590ZMay 15 22:56:06.578 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9402026-05-15T22:56:08.931ZMay 15 22:56:08.918 INFO trio bfd static routing test passed 🎉
9412026-05-15T22:56:08.931ZMay 15 22:56:08.919 INFO destroying runner for deployment mgtriobfd
9422026-05-15T22:56:08.931ZMay 15 22:56:08.919 INFO destroying deployment mgtriobfd
9432026-05-15T22:56:08.931ZMay 15 22:56:08.919 INFO destroying nodes
9442026-05-15T22:56:09.033ZMay 15 22:56:09.021 INFO destroying links
9452026-05-15T22:56:09.033ZMay 15 22:56:09.021 INFO destroying link mgtriobfd_ox_sn_vnic0
9462026-05-15T22:56:09.057ZMay 15 22:56:09.023 INFO destroying link mgtriobfd_ox_sn_sim0
9472026-05-15T22:56:09.057ZMay 15 22:56:09.024 INFO destroying link mgtriobfd_cr1_vn_vnic0
9482026-05-15T22:56:10.038ZMay 15 22:56:10.026 INFO destroying link mgtriobfd_cr1_vn_sim0
9492026-05-15T22:56:10.062ZMay 15 22:56:10.027 INFO destroying link mgtriobfd_ox_sn_vnic1
9502026-05-15T22:56:10.062ZMay 15 22:56:10.028 INFO destroying link mgtriobfd_ox_sn_sim1
9512026-05-15T22:56:10.062ZMay 15 22:56:10.029 INFO destroying link mgtriobfd_cr2_vn_vnic0
9522026-05-15T22:56:10.062ZMay 15 22:56:10.030 INFO destroying link mgtriobfd_cr2_vn_sim0
9532026-05-15T22:56:10.062ZMay 15 22:56:10.031 INFO destroying external links
9542026-05-15T22:56:10.062ZMay 15 22:56:10.032 INFO destroying external link mgtriobfd_ox_vn_vnic2
9552026-05-15T22:56:10.062ZMay 15 22:56:10.032 INFO destroying external link mgtriobfd_cr1_vn_vnic1
9562026-05-15T22:56:10.062ZMay 15 22:56:10.033 INFO destroying external link mgtriobfd_cr2_vn_vnic1
9572026-05-15T22:56:10.062ZMay 15 22:56:10.035 INFO destroying images
9582026-05-15T22:56:10.535ZMay 15 22:56:10.523 INFO destroying workspace at .falcon
9592026-05-15T22:56:10.559Zprocess exited: duration 699016 ms, exit code 0
 
9602026-05-15T22:56:10.609Zfound 0 output files