01KQ10YS42Z27TA054Q5JN5DYZ: falcon

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

Buildomat Job: 01KQ10Z3BQSY0SQ6P3P4S506MD

Tags:

Output:

SEQ GLOBAL TIME DETAILS
12026-04-25T00:51:02.430Zjob dependencies complete; ready to run (waiting for 16 m 10 s)
22026-04-25T00:54:16.766Zjob assigned to worker 01KQ11WQ5KPFJH22FD3WSM07R9 [factory edgar, gimlet/BRM42220010/843] (queued for 3 m 14 s)
32026-04-25T00:54:17.215Zdownloading input: /input/build-interop/work/testbed.tar.gz
42026-04-25T00:54:25.875Zdownloaded input: /input/build-interop/work/testbed.tar.gz
52026-04-25T00:54:25.876Zdownloading input: /input/build-interop/work/dhcp-server
62026-04-25T00:54:28.302Zdownloaded input: /input/build-interop/work/dhcp-server
72026-04-25T00:54:28.327Zdownloading input: /input/build/work/debug/ddmadm
82026-04-25T00:54:52.276Zdownloaded input: /input/build/work/debug/ddmadm
92026-04-25T00:54:52.276Zdownloading input: /input/build/work/debug/ddmd
102026-04-25T00:55:21.270Zdownloaded input: /input/build/work/debug/ddmd
112026-04-25T00:55:21.270Zdownloading input: /input/build/work/debug/mgadm
122026-04-25T00:55:48.887Zdownloaded input: /input/build/work/debug/mgadm
132026-04-25T00:55:48.887Zdownloading input: /input/build/work/debug/mgd
142026-04-25T00:56:21.610Zdownloaded input: /input/build/work/debug/mgd
152026-04-25T00:56:21.635Zdownloading input: /input/build/work/release/ddmadm
162026-04-25T00:56:23.682Zdownloaded input: /input/build/work/release/ddmadm
172026-04-25T00:56:23.707Zdownloading input: /input/build/work/release/ddmd
182026-04-25T00:56:26.093Zdownloaded input: /input/build/work/release/ddmd
192026-04-25T00:56:26.093Zdownloading input: /input/build/work/release/falcon-lab
202026-04-25T00:56:29.021Zdownloaded input: /input/build/work/release/falcon-lab
212026-04-25T00:56:29.021Zdownloading input: /input/build/work/release/mgadm
222026-04-25T00:56:31.639Zdownloaded input: /input/build/work/release/mgadm
232026-04-25T00:56:31.639Zdownloading input: /input/build/work/release/mgd
242026-04-25T00:56:35.106Zdownloaded input: /input/build/work/release/mgd
 
252026-04-25T00:56:35.106Zstarting task 0: "setup"
262026-04-25T00:56:35.132Z++ uname -s
272026-04-25T00:56:35.132Z+ kern=SunOS
282026-04-25T00:56:35.132Z+ build_user=build
292026-04-25T00:56:35.132Z+ build_uid=12345
302026-04-25T00:56:35.132Z+ work_dir=/work
312026-04-25T00:56:35.132Z+ input_dir=/input
322026-04-25T00:56:35.132Z+ [[ 0 == 12345 ]]
332026-04-25T00:56:35.132Z+ case "$kern" in
342026-04-25T00:56:35.132Z+ groupadd -g 12345 build
352026-04-25T00:56:35.157Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
362026-04-25T00:56:37.143Z+ zfs create -o mountpoint=/work rpool/work
372026-04-25T00:56:37.638Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
382026-04-25T00:56:37.664Z+ home_fs=
392026-04-25T00:56:37.664Z+ [[ '' == autofs ]]
402026-04-25T00:56:37.664Z+ mkdir -p /home/build
412026-04-25T00:56:37.664Z+ chown build:build /home/build /work
422026-04-25T00:56:39.652Z+ chmod 0700 /home/build /work
432026-04-25T00:56:39.677Zprocess exited: duration 4550 ms, exit code 0
 
442026-04-25T00:56:39.726Zstarting task 1: "authentication"
452026-04-25T00:56:39.823Zprocess exited: duration 96 ms, exit code 0
 
462026-04-25T00:56:39.873Zstarting task 2: "build"
472026-04-25T00:56:39.898Z+ set -e
482026-04-25T00:56:39.898Z+ banner zpool
492026-04-25T00:56:39.898Z
502026-04-25T00:56:39.898Z ###### ##### #### #### #
512026-04-25T00:56:39.898Z # # # # # # # #
522026-04-25T00:56:39.898Z # # # # # # # #
532026-04-25T00:56:39.898Z # ##### # # # # #
542026-04-25T00:56:39.898Z # # # # # # #
552026-04-25T00:56:39.898Z ###### # #### #### ######
562026-04-25T00:56:39.898Z
572026-04-25T00:56:39.898Z++ pfexec diskinfo -pH
582026-04-25T00:56:39.923Z++ sort -k8 -n -r
592026-04-25T00:56:39.923Z++ head -1
602026-04-25T00:56:39.923Z++ awk '{print $2}'
612026-04-25T00:56:39.948Z+ DISK=c9t0014EE81000BC3B1d0
622026-04-25T00:56:39.948Z+ export DISK
632026-04-25T00:56:39.948Z+ pfexec zpool create -o ashift=12 -f cpool c9t0014EE81000BC3B1d0
642026-04-25T00:56:40.012Z+ pfexec zfs create -o mountpoint=/ci cpool/ci
652026-04-25T00:56:40.040Z++ curl -s http://catacomb.eng.oxide.computer:12346/trim-me
662026-04-25T00:56:40.150Z+ [[ true =~ true ]]
672026-04-25T00:56:40.150Z+ pfexec zpool trim cpool
682026-04-25T00:56:40.175Z++ zpool status -t cpool
692026-04-25T00:56:40.200Z+ [[ ! pool: cpool
702026-04-25T00:56:40.200Z state: ONLINE
712026-04-25T00:56:40.200Z scan: none requested
722026-04-25T00:56:40.200Zconfig:
732026-04-25T00:56:40.200Z
742026-04-25T00:56:40.200Z NAME STATE READ WRITE CKSUM
752026-04-25T00:56:40.200Z cpool ONLINE 0 0 0
762026-04-25T00:56:40.200Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (1% trimmed, started at April 25, 2026 at 12:56:40 AM UTC)
772026-04-25T00:56:40.200Z
782026-04-25T00:56:40.200Zerrors: No known data errors =~ 100% ]]
792026-04-25T00:56:40.200Z+ sleep 10
802026-04-25T00:56:50.185Z++ zpool status -t cpool
812026-04-25T00:56:50.210Z+ [[ ! pool: cpool
822026-04-25T00:56:50.210Z state: ONLINE
832026-04-25T00:56:50.210Z scan: none requested
842026-04-25T00:56:50.210Zconfig:
852026-04-25T00:56:50.210Z
862026-04-25T00:56:50.210Z NAME STATE READ WRITE CKSUM
872026-04-25T00:56:50.210Z cpool ONLINE 0 0 0
882026-04-25T00:56:50.210Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (69% trimmed, started at April 25, 2026 at 12:56:40 AM UTC)
892026-04-25T00:56:50.210Z
902026-04-25T00:56:50.210Zerrors: No known data errors =~ 100% ]]
912026-04-25T00:56:50.210Z+ sleep 10
922026-04-25T00:57:00.198Z++ zpool status -t cpool
932026-04-25T00:57:00.223Z+ [[ ! pool: cpool
942026-04-25T00:57:00.224Z state: ONLINE
952026-04-25T00:57:00.224Z scan: none requested
962026-04-25T00:57:00.224Zconfig:
972026-04-25T00:57:00.224Z
982026-04-25T00:57:00.224Z NAME STATE READ WRITE CKSUM
992026-04-25T00:57:00.224Z cpool ONLINE 0 0 0
1002026-04-25T00:57:00.224Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (100% trimmed, completed at April 25, 2026 at 12:56:54 AM UTC)
1012026-04-25T00:57:00.224Z
1022026-04-25T00:57:00.224Zerrors: No known data errors =~ 100% ]]
1032026-04-25T00:57:00.224Z+ pfexec chown 12345 /ci
1042026-04-25T00:57:00.224Z+ cd /ci
1052026-04-25T00:57:00.224Z+ export FALCON_DATASET=cpool/falcon
1062026-04-25T00:57:00.224Z+ FALCON_DATASET=cpool/falcon
1072026-04-25T00:57:00.224Z+ banner setup
1082026-04-25T00:57:00.224Z
1092026-04-25T00:57:00.224Z #### ###### ##### # # #####
1102026-04-25T00:57:00.224Z # # # # # # #
1112026-04-25T00:57:00.224Z #### ##### # # # # #
1122026-04-25T00:57:00.224Z # # # # # #####
1132026-04-25T00:57:00.224Z # # # # # # #
1142026-04-25T00:57:00.224Z #### ###### # #### #
1152026-04-25T00:57:00.224Z
1162026-04-25T00:57:00.224Z+ cp /input/build-interop/work/dhcp-server .
1172026-04-25T00:57:00.562Z+ cp /input/build/work/release/falcon-lab .
1182026-04-25T00:57:00.616Z+ cp /input/build/work/release/mgd .
1192026-04-25T00:57:00.683Z+ cp /input/build/work/release/ddmd .
1202026-04-25T00:57:00.732Z+ chmod +x dhcp-server falcon-lab mgd ddmd
1212026-04-25T00:57:00.758Z+ mkdir -p cargo-bay
1222026-04-25T00:57:00.759Z+ mv mgd cargo-bay/
1232026-04-25T00:57:00.759Z+ mv ddmd cargo-bay/
1242026-04-25T00:57:00.759Z+ export EXT_INTERFACE=igb0
1252026-04-25T00:57:00.759Z+ EXT_INTERFACE=igb0
1262026-04-25T00:57:00.759Z++ bmat address ls -f extra -Ho first
1272026-04-25T00:57:00.783Z+ first=10.151.6.164
1282026-04-25T00:57:00.808Z++ bmat address ls -f extra -Ho last
1292026-04-25T00:57:00.809Z+ last=10.151.6.227
1302026-04-25T00:57:00.833Z++ bmat address ls -f extra -Ho gateway
1312026-04-25T00:57:00.833Z+ gw=10.151.6.1
1322026-04-25T00:57:00.858Z++ ipadm show-addr igb0/dhcp -po ADDR
1332026-04-25T00:57:00.858Z++ sed 's#/.*##g'
1342026-04-25T00:57:00.858Z+ server=10.151.6.100
1352026-04-25T00:57:00.858Z+ RUST_LOG=debug
1362026-04-25T00:57:00.858Z+ pfexec ./falcon-lab run trio-unnumbered
1372026-04-25T00:57:00.858Z+ pfexec ./dhcp-server 10.151.6.164 10.151.6.227 10.151.6.1 10.151.6.100
1382026-04-25T00:57:00.883ZApr 25 00:57:00.847 DEBG using default route interface igb0
1392026-04-25T00:57:00.883ZApr 25 00:57:00.847 DEBG using default route interface igb0
1402026-04-25T00:57:00.883ZApr 25 00:57:00.847 DEBG using default route interface igb0
1412026-04-25T00:57:00.883ZApr 25 00:57:00.847 INFO launching runner: deployment(mgtriou) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
1422026-04-25T00:57:00.883ZApr 25 00:57:00.847 INFO starting preflight for deployment mgtriou
1432026-04-25T00:57:00.883ZApr 25 00:57:00.847 INFO propolis-server binary not found
1442026-04-25T00:57:00.883ZApr 25 00:57:00.847 INFO downloading propolis server rev 36f20be9bb4c3b362029237f5feb6377c982395f, writing to .falcon/bin/propolis-server
1452026-04-25T00:57:04.765ZApr 25 00:57:04.746 INFO ovmf fd not found
1462026-04-25T00:57:04.765ZApr 25 00:57:04.746 INFO downloading ovmf
1472026-04-25T00:57:05.159ZApr 25 00:57:05.140 INFO base image for helios-2.9 does not exist, attempting to install
1482026-04-25T00:57:05.159ZApr 25 00:57:05.140 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/helios-2.9_0.raw.xz
1492026-04-25T00:57:33.285ZApr 25 00:57:33.266 INFO extracting image to /tmp/helios-2.9_0.raw
1502026-04-25T00:58:06.934ZApr 25 00:58:06.916 INFO creating zvol cpool/falcon/img/helios-2.9 of size 4508880896
1512026-04-25T00:58:06.985ZApr 25 00:58:06.967 INFO copying image data to zvol
1522026-04-25T00:58:17.574ZApr 25 00:58:17.558 INFO creating zfs snapshot cpool/falcon/img/helios-2.9@base
1532026-04-25T00:58:20.871ZApr 25 00:58:20.855 INFO base image for debian-13.2 does not exist, attempting to install
1542026-04-25T00:58:20.871ZApr 25 00:58:20.855 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz
1552026-04-25T00:58:41.315ZApr 25 00:58:41.301 INFO extracting image to /tmp/debian-13.2_0.raw
1562026-04-25T00:59:02.209ZApr 25 00:59:02.194 INFO creating zvol cpool/falcon/img/debian-13.2 of size 3221229568
1572026-04-25T00:59:02.233ZApr 25 00:59:02.219 INFO copying image data to zvol
1582026-04-25T00:59:10.326ZApr 25 00:59:10.312 INFO creating zfs snapshot cpool/falcon/img/debian-13.2@base
1592026-04-25T00:59:13.182ZApr 25 00:59:13.167 INFO base image for eos-4.35 does not exist, attempting to install
1602026-04-25T00:59:13.182ZApr 25 00:59:13.167 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz
1612026-04-25T00:59:55.945ZApr 25 00:59:55.931 INFO extracting image to /tmp/eos-4.35_0.raw
1622026-04-25T01:01:19.851ZApr 25 01:01:19.838 INFO creating zvol cpool/falcon/img/eos-4.35 of size 21474840576
1632026-04-25T01:01:19.877ZApr 25 01:01:19.865 INFO copying image data to zvol
1642026-04-25T01:02:08.663ZApr 25 01:02:08.651 INFO creating zfs snapshot cpool/falcon/img/eos-4.35@base
1652026-04-25T01:02:12.023ZApr 25 01:02:12.011 INFO creating links
1662026-04-25T01:02:12.023ZApr 25 01:02:12.011 DEBG destroying link mgtriou_ox_sn_vnic0
1672026-04-25T01:02:12.048ZApr 25 01:02:12.011 DEBG destroying link mgtriou_ox_sn_sim0
1682026-04-25T01:02:12.048ZApr 25 01:02:12.011 INFO creating simnet link 'mgtriou_ox_sn_sim0'
1692026-04-25T01:02:12.048ZApr 25 01:02:12.013 INFO creating vnic link 'mgtriou_ox_sn_vnic0'
1702026-04-25T01:02:12.048ZApr 25 01:02:12.020 DEBG link pair created
1712026-04-25T01:02:12.048ZApr 25 01:02:12.020 DEBG destroying link mgtriou_cr1_vn_vnic0
1722026-04-25T01:02:12.048ZApr 25 01:02:12.020 DEBG destroying link mgtriou_cr1_vn_sim0
1732026-04-25T01:02:12.048ZApr 25 01:02:12.020 INFO creating simnet link 'mgtriou_cr1_vn_sim0'
1742026-04-25T01:02:12.048ZApr 25 01:02:12.022 INFO creating vnic link 'mgtriou_cr1_vn_vnic0'
1752026-04-25T01:02:12.048ZApr 25 01:02:12.028 DEBG link pair created
1762026-04-25T01:02:12.048ZApr 25 01:02:12.028 DEBG destroying link mgtriou_ox_sn_vnic1
1772026-04-25T01:02:12.048ZApr 25 01:02:12.028 DEBG destroying link mgtriou_ox_sn_sim1
1782026-04-25T01:02:12.048ZApr 25 01:02:12.028 INFO creating simnet link 'mgtriou_ox_sn_sim1'
1792026-04-25T01:02:12.048ZApr 25 01:02:12.029 INFO creating vnic link 'mgtriou_ox_sn_vnic1'
1802026-04-25T01:02:12.048ZApr 25 01:02:12.035 DEBG link pair created
1812026-04-25T01:02:12.048ZApr 25 01:02:12.036 DEBG destroying link mgtriou_cr2_vn_vnic0
1822026-04-25T01:02:12.048ZApr 25 01:02:12.036 DEBG destroying link mgtriou_cr2_vn_sim0
1832026-04-25T01:02:12.049ZApr 25 01:02:12.036 INFO creating simnet link 'mgtriou_cr2_vn_sim0'
1842026-04-25T01:02:12.073ZApr 25 01:02:12.037 INFO creating vnic link 'mgtriou_cr2_vn_vnic0'
1852026-04-25T01:02:12.073ZApr 25 01:02:12.043 DEBG link pair created
1862026-04-25T01:02:12.073ZApr 25 01:02:12.043 INFO creating external links
1872026-04-25T01:02:12.073ZApr 25 01:02:12.043 DEBG destroying external link mgtriou_ox_vn_vnic2
1882026-04-25T01:02:12.073ZApr 25 01:02:12.043 INFO creating external link mgtriou_ox_vn_vnic2
1892026-04-25T01:02:12.073ZApr 25 01:02:12.045 DEBG external link mgtriou_ox_vn_vnic2@igb0 created
1902026-04-25T01:02:12.074ZApr 25 01:02:12.045 DEBG destroying external link mgtriou_cr1_vn_vnic1
1912026-04-25T01:02:12.074ZApr 25 01:02:12.045 INFO creating external link mgtriou_cr1_vn_vnic1
1922026-04-25T01:02:12.074ZApr 25 01:02:12.046 DEBG external link mgtriou_cr1_vn_vnic1@igb0 created
1932026-04-25T01:02:12.074ZApr 25 01:02:12.046 DEBG destroying external link mgtriou_cr2_vn_vnic1
1942026-04-25T01:02:12.074ZApr 25 01:02:12.046 INFO creating external link mgtriou_cr2_vn_vnic1
1952026-04-25T01:02:12.074ZApr 25 01:02:12.047 DEBG external link mgtriou_cr2_vn_vnic1@igb0 created
1962026-04-25T01:02:12.074ZApr 25 01:02:12.047 INFO creating nodes
1972026-04-25T01:02:12.074ZApr 25 01:02:12.047 INFO ox: launching node
1982026-04-25T01:02:12.074ZApr 25 01:02:12.050 INFO cr1: launching node
1992026-04-25T01:02:12.074ZApr 25 01:02:12.052 INFO cr2: launching node
2002026-04-25T01:02:12.099ZApr 25 01:02:12.066 INFO launched instance ox with pid 848 on port 55977
2012026-04-25T01:02:12.099ZApr 25 01:02:12.066 INFO ox: instance ensure
2022026-04-25T01:02:12.099ZApr 25 01:02:12.066 INFO launched instance cr1 with pid 849 on port 54664
2032026-04-25T01:02:12.099ZApr 25 01:02:12.066 INFO cr1: instance ensure
2042026-04-25T01:02:12.099ZApr 25 01:02:12.067 INFO launched instance cr2 with pid 850 on port 54726
2052026-04-25T01:02:12.099ZApr 25 01:02:12.067 INFO cr2: instance ensure
2062026-04-25T01:02:14.399ZApr 25 01:02:14.387 INFO cr2: instance run
2072026-04-25T01:02:14.424ZApr 25 01:02:14.387 DEBG [sc] cr2: starting
2082026-04-25T01:02:14.424ZApr 25 01:02:14.387 DEBG [sc] cr2: connecting to [::1]:54726
2092026-04-25T01:02:14.424ZApr 25 01:02:14.388 DEBG [sc] cr2 waiting for prompt
2102026-04-25T01:02:14.490ZApr 25 01:02:14.478 INFO ox: instance run
2112026-04-25T01:02:14.514ZApr 25 01:02:14.478 DEBG [sc] ox: starting
2122026-04-25T01:02:14.514ZApr 25 01:02:14.478 DEBG [sc] ox: connecting to [::1]:55977
2132026-04-25T01:02:14.515ZApr 25 01:02:14.479 DEBG [sc] ox waiting for prompt
2142026-04-25T01:02:14.539ZApr 25 01:02:14.518 INFO cr1: instance run
2152026-04-25T01:02:14.539ZApr 25 01:02:14.519 DEBG [sc] cr1: starting
2162026-04-25T01:02:14.539ZApr 25 01:02:14.519 DEBG [sc] cr1: connecting to [::1]:54664
2172026-04-25T01:02:14.539ZApr 25 01:02:14.520 DEBG [sc] cr1 waiting for prompt
2182026-04-25T01:02:31.515ZApr 25 01:02:31.503 DEBG [sc] cr1: logging in
2192026-04-25T01:02:31.897ZApr 25 01:02:31.885 INFO cr1: mounting /opt/cargo-bay
2202026-04-25T01:02:31.898ZApr 25 01:02:31.885 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2212026-04-25T01:02:31.923ZApr 25 01:02:31.909 DEBG [sc] cr1: executing command `cd`
2222026-04-25T01:02:31.948ZApr 25 01:02:31.920 INFO cr1: finished mounting /opt/cargo-bay
2232026-04-25T01:02:31.948ZApr 25 01:02:31.920 DEBG [sc] cr1: executing command `hostname cr1`
2242026-04-25T01:02:31.948ZApr 25 01:02:31.931 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
2252026-04-25T01:02:31.972ZApr 25 01:02:31.942 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
2262026-04-25T01:02:31.972ZApr 25 01:02:31.953 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
2272026-04-25T01:02:31.997ZApr 25 01:02:31.964 INFO cr1: logging out
2282026-04-25T01:02:34.040ZApr 25 01:02:34.028 INFO cr1: logged out
2292026-04-25T01:02:35.053ZApr 25 01:02:35.041 DEBG [sc] ox: logging in
2302026-04-25T01:02:35.230ZApr 25 01:02:35.219 INFO ox: mounting /opt/cargo-bay
2312026-04-25T01:02:35.230ZApr 25 01:02:35.219 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2322026-04-25T01:02:36.004ZApr 25 01:02:35.992 DEBG [sc] cr2: logging in
2332026-04-25T01:02:36.394ZApr 25 01:02:36.382 DEBG [sc] ox: executing command `cd`
2342026-04-25T01:02:36.419ZApr 25 01:02:36.394 INFO ox: finished mounting /opt/cargo-bay
2352026-04-25T01:02:36.419ZApr 25 01:02:36.394 DEBG [sc] ox: executing command `hostname ox`
2362026-04-25T01:02:36.419ZApr 25 01:02:36.405 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
2372026-04-25T01:02:36.444ZApr 25 01:02:36.415 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
2382026-04-25T01:02:36.444ZApr 25 01:02:36.426 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
2392026-04-25T01:02:36.444ZApr 25 01:02:36.428 INFO cr2: mounting /opt/cargo-bay
2402026-04-25T01:02:36.444ZApr 25 01:02:36.428 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2412026-04-25T01:02:36.469ZApr 25 01:02:36.448 INFO ox: logging out
2422026-04-25T01:02:36.469ZApr 25 01:02:36.450 DEBG [sc] cr2: executing command `cd`
2432026-04-25T01:02:36.493ZApr 25 01:02:36.461 INFO cr2: finished mounting /opt/cargo-bay
2442026-04-25T01:02:36.493ZApr 25 01:02:36.461 DEBG [sc] cr2: executing command `hostname cr2`
2452026-04-25T01:02:36.493ZApr 25 01:02:36.472 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
2462026-04-25T01:02:36.518ZApr 25 01:02:36.483 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
2472026-04-25T01:02:36.518ZApr 25 01:02:36.495 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
2482026-04-25T01:02:36.518ZApr 25 01:02:36.506 INFO cr2: logging out
2492026-04-25T01:02:36.542ZApr 25 01:02:36.526 INFO ox: logged out
2502026-04-25T01:02:39.370ZApr 25 01:02:39.359 INFO cr2: logged out
2512026-04-25T01:02:39.395ZApr 25 01:02:39.359 DEBG [sc] ox: starting
2522026-04-25T01:02:39.395ZApr 25 01:02:39.359 DEBG [sc] ox: connecting to [::1]:55977
2532026-04-25T01:02:39.395ZApr 25 01:02:39.360 DEBG [sc] ox waiting for prompt
2542026-04-25T01:02:39.395ZApr 25 01:02:39.371 DEBG [sc] ox: logging in
2552026-04-25T01:02:39.470ZApr 25 01:02:39.458 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
2562026-04-25T01:02:44.867ZApr 25 01:02:44.855 DEBG [sc] ox: starting
2572026-04-25T01:02:44.868ZApr 25 01:02:44.856 DEBG [sc] ox: connecting to [::1]:55977
2582026-04-25T01:02:44.892ZApr 25 01:02:44.856 DEBG [sc] ox waiting for prompt
2592026-04-25T01:02:44.893ZApr 25 01:02:44.866 DEBG [sc] ox: logging in
2602026-04-25T01:02:44.955ZApr 25 01:02:44.943 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
2612026-04-25T01:02:45.042ZApr 25 01:02:45.031 DEBG [sc] ox: starting
2622026-04-25T01:02:45.043ZApr 25 01:02:45.031 DEBG [sc] ox: connecting to [::1]:55977
2632026-04-25T01:02:45.068ZApr 25 01:02:45.031 DEBG [sc] ox waiting for prompt
2642026-04-25T01:02:45.068ZApr 25 01:02:45.042 DEBG [sc] ox: logging in
2652026-04-25T01:02:45.143ZApr 25 01:02:45.131 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
2662026-04-25T01:02:45.209ZApr 25 01:02:45.197 INFO cr1: installing frr
2672026-04-25T01:02:45.209ZApr 25 01:02:45.197 INFO ox: setting up npuvm
2682026-04-25T01:02:45.209ZApr 25 01:02:45.197 INFO waiting for ceos to initialize
2692026-04-25T01:02:45.234ZApr 25 01:02:45.197 DEBG [sc] cr2: starting
2702026-04-25T01:02:45.234ZApr 25 01:02:45.197 DEBG [sc] cr2: connecting to [::1]:54726
2712026-04-25T01:02:45.234ZApr 25 01:02:45.197 DEBG [sc] cr1: starting
2722026-04-25T01:02:45.234ZApr 25 01:02:45.197 DEBG [sc] ox: starting
2732026-04-25T01:02:45.234ZApr 25 01:02:45.197 DEBG [sc] cr1: connecting to [::1]:54664
2742026-04-25T01:02:45.234ZApr 25 01:02:45.197 DEBG [sc] ox: connecting to [::1]:55977
2752026-04-25T01:02:45.234ZApr 25 01:02:45.198 DEBG [sc] ox waiting for prompt
2762026-04-25T01:02:45.234ZApr 25 01:02:45.198 DEBG [sc] cr2 waiting for prompt
2772026-04-25T01:02:45.234ZApr 25 01:02:45.198 DEBG [sc] cr1 waiting for prompt
2782026-04-25T01:02:45.234ZApr 25 01:02:45.208 DEBG [sc] ox: logging in
2792026-04-25T01:02:45.234ZApr 25 01:02:45.208 DEBG [sc] cr1: logging in
2802026-04-25T01:02:45.234ZApr 25 01:02:45.209 DEBG [sc] cr2: logging in
2812026-04-25T01:02:45.308ZApr 25 01:02:45.296 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
2822026-04-25T01:02:45.374ZApr 25 01:02:45.362 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
2832026-04-25T01:02:45.551ZApr 25 01:02:45.539 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
2842026-04-25T01:02:47.600ZApr 25 01:02:47.589 INFO cr2: executing eos script show version
2852026-04-25T01:02:47.600ZApr 25 01:02:47.589 DEBG [sc] cr2: starting
2862026-04-25T01:02:47.600ZApr 25 01:02:47.589 DEBG [sc] cr2: connecting to [::1]:54726
2872026-04-25T01:02:47.625ZApr 25 01:02:47.589 DEBG [sc] cr2 waiting for prompt
2882026-04-25T01:02:47.625ZApr 25 01:02:47.599 DEBG [sc] cr2: logging in
2892026-04-25T01:02:47.754ZApr 25 01:02:47.743 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
2902026-04-25T01:02:50.737ZApr 25 01:02:50.725 DEBG [sc] ox: starting
2912026-04-25T01:02:50.737ZApr 25 01:02:50.725 DEBG [sc] ox: connecting to [::1]:55977
2922026-04-25T01:02:50.762ZApr 25 01:02:50.726 DEBG [sc] ox waiting for prompt
2932026-04-25T01:02:50.762ZApr 25 01:02:50.736 DEBG [sc] ox: logging in
2942026-04-25T01:02:50.837ZApr 25 01:02:50.825 DEBG [sc] ox: executing command `chmod +x npuvm`
2952026-04-25T01:02:50.903ZApr 25 01:02:50.892 DEBG [sc] ox: starting
2962026-04-25T01:02:50.903ZApr 25 01:02:50.892 DEBG [sc] ox: connecting to [::1]:55977
2972026-04-25T01:02:50.928ZApr 25 01:02:50.892 DEBG [sc] ox waiting for prompt
2982026-04-25T01:02:50.928ZApr 25 01:02:50.902 DEBG [sc] ox: logging in
2992026-04-25T01:02:50.992ZApr 25 01:02:50.980 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
3002026-04-25T01:02:56.830ZApr 25 01:02:56.818 DEBG [sc] cr2: starting
3012026-04-25T01:02:56.831ZApr 25 01:02:56.818 DEBG [sc] cr2: connecting to [::1]:54726
3022026-04-25T01:02:56.855ZApr 25 01:02:56.819 DEBG [sc] cr2 waiting for prompt
3032026-04-25T01:02:56.855ZApr 25 01:02:56.829 DEBG [sc] cr2: logging in
3042026-04-25T01:02:56.974ZApr 25 01:02:56.962 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3052026-04-25T01:02:59.087ZApr 25 01:02:59.075 INFO cr2: executing eos script show version
3062026-04-25T01:02:59.087ZApr 25 01:02:59.075 DEBG [sc] cr2: starting
3072026-04-25T01:02:59.087ZApr 25 01:02:59.076 DEBG [sc] cr2: connecting to [::1]:54726
3082026-04-25T01:02:59.112ZApr 25 01:02:59.076 DEBG [sc] cr2 waiting for prompt
3092026-04-25T01:02:59.112ZApr 25 01:02:59.086 DEBG [sc] cr2: logging in
3102026-04-25T01:02:59.274ZApr 25 01:02:59.263 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3112026-04-25T01:03:01.653ZApr 25 01:03:01.641 DEBG [sc] cr2: starting
3122026-04-25T01:03:01.653ZApr 25 01:03:01.641 DEBG [sc] cr2: connecting to [::1]:54726
3132026-04-25T01:03:01.678ZApr 25 01:03:01.641 DEBG [sc] cr2 waiting for prompt
3142026-04-25T01:03:01.678ZApr 25 01:03:01.651 DEBG [sc] cr2: logging in
3152026-04-25T01:03:01.818ZApr 25 01:03:01.806 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3162026-04-25T01:03:03.972ZApr 25 01:03:03.960 INFO cr2: executing eos script show version
3172026-04-25T01:03:03.972ZApr 25 01:03:03.960 DEBG [sc] cr2: starting
3182026-04-25T01:03:03.972ZApr 25 01:03:03.960 DEBG [sc] cr2: connecting to [::1]:54726
3192026-04-25T01:03:03.997ZApr 25 01:03:03.960 DEBG [sc] cr2 waiting for prompt
3202026-04-25T01:03:03.997ZApr 25 01:03:03.969 DEBG [sc] cr2: logging in
3212026-04-25T01:03:04.136ZApr 25 01:03:04.124 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3222026-04-25T01:03:06.674ZApr 25 01:03:06.662 INFO cr2: executing eos script
3232026-04-25T01:03:06.674Z enable
3242026-04-25T01:03:06.674Z configure
3252026-04-25T01:03:06.674Z ipv6 unicast-routing
3262026-04-25T01:03:06.674Z ip routing ipv6 interfaces
3272026-04-25T01:03:06.674Z ip routing
3282026-04-25T01:03:06.674Z ip route 1.2.3.0/24 null0
3292026-04-25T01:03:06.674Z ipv6 route fd99::/64 null0
3302026-04-25T01:03:06.674Z interface et1
3312026-04-25T01:03:06.674Z no switchport
3322026-04-25T01:03:06.674Z ipv6 enable
3332026-04-25T01:03:06.674Z
3342026-04-25T01:03:06.674Z router bgp 45
3352026-04-25T01:03:06.674Z router-id 1.2.3.1
3362026-04-25T01:03:06.674Z no bgp default ipv4-unicast
3372026-04-25T01:03:06.674Z timers bgp 2 6
3382026-04-25T01:03:06.674Z neighbor ebgp peer group
3392026-04-25T01:03:06.674Z neighbor ebgp remote-as 33
3402026-04-25T01:03:06.674Z neighbor interface Et1 peer-group ebgp
3412026-04-25T01:03:06.674Z address-family ipv4
3422026-04-25T01:03:06.674Z neighbor ebgp activate
3432026-04-25T01:03:06.674Z neighbor ebgp next-hop address-family ipv6 originate
3442026-04-25T01:03:06.674Z network 1.2.3.0/24
3452026-04-25T01:03:06.674Z exit
3462026-04-25T01:03:06.674Z address-family ipv6
3472026-04-25T01:03:06.674Z neighbor ebgp activate
3482026-04-25T01:03:06.674Z neighbor ebgp next-hop address-family ipv6 originate
3492026-04-25T01:03:06.674Z network fd99::/64
3502026-04-25T01:03:06.674Z exit
3512026-04-25T01:03:06.674Z exit
3522026-04-25T01:03:06.674Z
3532026-04-25T01:03:06.674ZApr 25 01:03:06.662 DEBG [sc] cr2: starting
3542026-04-25T01:03:06.675ZApr 25 01:03:06.662 DEBG [sc] cr2: connecting to [::1]:54726
3552026-04-25T01:03:06.700ZApr 25 01:03:06.662 DEBG [sc] cr2 waiting for prompt
3562026-04-25T01:03:06.700ZApr 25 01:03:06.673 DEBG [sc] cr2: logging in
3572026-04-25T01:03:06.828ZApr 25 01:03:06.816 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
3582026-04-25T01:03:06.828Z enable
3592026-04-25T01:03:06.828Z configure
3602026-04-25T01:03:06.828Z ipv6 unicast-routing
3612026-04-25T01:03:06.828Z ip routing ipv6 interfaces
3622026-04-25T01:03:06.828Z ip routing
3632026-04-25T01:03:06.828Z ip route 1.2.3.0/24 null0
3642026-04-25T01:03:06.828Z ipv6 route fd99::/64 null0
3652026-04-25T01:03:06.829Z interface et1
3662026-04-25T01:03:06.829Z no switchport
3672026-04-25T01:03:06.829Z ipv6 enable
3682026-04-25T01:03:06.829Z
3692026-04-25T01:03:06.829Z router bgp 45
3702026-04-25T01:03:06.829Z router-id 1.2.3.1
3712026-04-25T01:03:06.829Z no bgp default ipv4-unicast
3722026-04-25T01:03:06.829Z timers bgp 2 6
3732026-04-25T01:03:06.829Z neighbor ebgp peer group
3742026-04-25T01:03:06.829Z neighbor ebgp remote-as 33
3752026-04-25T01:03:06.829Z neighbor interface Et1 peer-group ebgp
3762026-04-25T01:03:06.829Z address-family ipv4
3772026-04-25T01:03:06.829Z neighbor ebgp activate
3782026-04-25T01:03:06.829Z neighbor ebgp next-hop address-family ipv6 originate
3792026-04-25T01:03:06.829Z network 1.2.3.0/24
3802026-04-25T01:03:06.829Z exit
3812026-04-25T01:03:06.829Z address-family ipv6
3822026-04-25T01:03:06.829Z neighbor ebgp activate
3832026-04-25T01:03:06.829Z neighbor ebgp next-hop address-family ipv6 originate
3842026-04-25T01:03:06.829Z network fd99::/64
3852026-04-25T01:03:06.829Z exit
3862026-04-25T01:03:06.829Z exit
3872026-04-25T01:03:06.829Z '`
3882026-04-25T01:03:22.570ZApr 25 01:03:22.559 INFO cr1: enabling frr daemon bgpd
3892026-04-25T01:03:22.570ZApr 25 01:03:22.559 DEBG [sc] cr1: starting
3902026-04-25T01:03:22.595ZApr 25 01:03:22.559 DEBG [sc] cr1: connecting to [::1]:54664
3912026-04-25T01:03:22.595ZApr 25 01:03:22.559 DEBG [sc] cr1 waiting for prompt
3922026-04-25T01:03:22.595ZApr 25 01:03:22.569 DEBG [sc] cr1: logging in
3932026-04-25T01:03:22.715ZApr 25 01:03:22.703 DEBG [sc] cr1: executing command `sed -i 's/bgpd=no/bgpd=yes/g' /etc/frr/daemons`
3942026-04-25T01:03:24.791ZApr 25 01:03:24.779 DEBG [sc] cr1: starting
3952026-04-25T01:03:24.791ZApr 25 01:03:24.779 DEBG [sc] cr1: connecting to [::1]:54664
3962026-04-25T01:03:24.817ZApr 25 01:03:24.779 DEBG [sc] cr1 waiting for prompt
3972026-04-25T01:03:24.817ZApr 25 01:03:24.790 DEBG [sc] cr1: logging in
3982026-04-25T01:03:24.955ZApr 25 01:03:24.944 DEBG [sc] cr1: executing command `systemctl restart frr`
3992026-04-25T01:03:32.579ZApr 25 01:03:32.568 INFO cr1: executing frr script
4002026-04-25T01:03:32.580Z configure
4012026-04-25T01:03:32.580Z ip forwarding
4022026-04-25T01:03:32.580Z ipv6 forwarding
4032026-04-25T01:03:32.580Z ip route 1.2.3.0/24 null0
4042026-04-25T01:03:32.580Z ipv6 route fd99::/64 null0
4052026-04-25T01:03:32.580Z router bgp 44
4062026-04-25T01:03:32.580Z no bgp ebgp-requires-policy
4072026-04-25T01:03:32.580Z timers bgp 2 6
4082026-04-25T01:03:32.580Z neighbor enp0s8 interface remote-as external
4092026-04-25T01:03:32.580Z neighbor enp0s8 timers connect 1
4102026-04-25T01:03:32.580Z address-family ipv4 unicast
4112026-04-25T01:03:32.580Z network 1.2.3.0/24
4122026-04-25T01:03:32.580Z neighbor enp0s8 activate
4132026-04-25T01:03:32.580Z exit-address-family
4142026-04-25T01:03:32.580Z address-family ipv6 unicast
4152026-04-25T01:03:32.580Z network fd99::/64
4162026-04-25T01:03:32.580Z neighbor enp0s8 activate
4172026-04-25T01:03:32.580Z exit-address-family
4182026-04-25T01:03:32.580Z exit
4192026-04-25T01:03:32.580Z
4202026-04-25T01:03:32.580ZApr 25 01:03:32.568 DEBG [sc] cr1: starting
4212026-04-25T01:03:32.605ZApr 25 01:03:32.568 DEBG [sc] cr1: connecting to [::1]:54664
4222026-04-25T01:03:32.605ZApr 25 01:03:32.568 DEBG [sc] cr1 waiting for prompt
4232026-04-25T01:03:32.605ZApr 25 01:03:32.578 DEBG [sc] cr1: logging in
4242026-04-25T01:03:32.723ZApr 25 01:03:32.711 DEBG [sc] cr1: executing command `vtysh -c '' -c ' configure' -c ' ip forwarding' -c ' ipv6 forwarding' -c ' ip route 1.2.3.0/24 null0' -c ' ipv6 route fd99::/64 null0' -c ' router bgp 44' -c ' no bgp ebgp-requires-policy' -c ' timers bgp 2 6' -c ' neighbor enp0s8 interface remote-as external' -c ' neighbor enp0s8 timers connect 1 ' -c ' address-family ipv4 unicast' -c ' network 1.2.3.0/24' -c ' neighbor enp0s8 activate' -c ' exit-address-family' -c ' address-family ipv6 unicast' -c ' network fd99::/64' -c ' neighbor enp0s8 activate' -c ' exit-address-family' -c ' exit' -c ' '`
4252026-04-25T01:04:34.771ZApr 25 01:04:34.759 DEBG [sc] ox: starting
4262026-04-25T01:04:34.771ZApr 25 01:04:34.759 DEBG [sc] ox: connecting to [::1]:55977
4272026-04-25T01:04:34.796ZApr 25 01:04:34.760 DEBG [sc] ox waiting for prompt
4282026-04-25T01:04:34.796ZApr 25 01:04:34.770 DEBG [sc] ox: logging in
4292026-04-25T01:04:34.861ZApr 25 01:04:34.850 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
4302026-04-25T01:04:35.159ZApr 25 01:04:35.148 DEBG [sc] ox: starting
4312026-04-25T01:04:35.160ZApr 25 01:04:35.148 DEBG [sc] ox: connecting to [::1]:55977
4322026-04-25T01:04:35.184ZApr 25 01:04:35.148 DEBG [sc] ox waiting for prompt
4332026-04-25T01:04:35.184ZApr 25 01:04:35.159 DEBG [sc] ox: logging in
4342026-04-25T01:04:35.248ZApr 25 01:04:35.237 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4352026-04-25T01:04:36.271ZApr 25 01:04:36.259 DEBG [sc] ox: starting
4362026-04-25T01:04:36.271ZApr 25 01:04:36.259 DEBG [sc] ox: connecting to [::1]:55977
4372026-04-25T01:04:36.296ZApr 25 01:04:36.260 DEBG [sc] ox waiting for prompt
4382026-04-25T01:04:36.296ZApr 25 01:04:36.260 DEBG [sc] ox: logging in
4392026-04-25T01:04:36.349ZApr 25 01:04:36.337 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4402026-04-25T01:04:36.405ZApr 25 01:04:36.393 DEBG [sc] ox: starting
4412026-04-25T01:04:36.405ZApr 25 01:04:36.393 DEBG [sc] ox: connecting to [::1]:55977
4422026-04-25T01:04:36.429ZApr 25 01:04:36.394 DEBG [sc] ox waiting for prompt
4432026-04-25T01:04:36.429ZApr 25 01:04:36.404 DEBG [sc] ox: logging in
4442026-04-25T01:04:36.494ZApr 25 01:04:36.482 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
4452026-04-25T01:04:36.549ZApr 25 01:04:36.538 DEBG [sc] ox: starting
4462026-04-25T01:04:36.550ZApr 25 01:04:36.538 DEBG [sc] ox: connecting to [::1]:55977
4472026-04-25T01:04:36.574ZApr 25 01:04:36.539 DEBG [sc] ox waiting for prompt
4482026-04-25T01:04:36.574ZApr 25 01:04:36.548 DEBG [sc] ox: logging in
4492026-04-25T01:04:36.637ZApr 25 01:04:36.626 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
4502026-04-25T01:04:36.693ZApr 25 01:04:36.682 DEBG [sc] ox: starting
4512026-04-25T01:04:36.693ZApr 25 01:04:36.682 DEBG [sc] ox: connecting to [::1]:55977
4522026-04-25T01:04:36.718ZApr 25 01:04:36.683 DEBG [sc] ox waiting for prompt
4532026-04-25T01:04:36.718ZApr 25 01:04:36.693 DEBG [sc] ox: logging in
4542026-04-25T01:04:36.781ZApr 25 01:04:36.769 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
4552026-04-25T01:04:36.837ZApr 25 01:04:36.825 DEBG [sc] ox: starting
4562026-04-25T01:04:36.837ZApr 25 01:04:36.825 DEBG [sc] ox: connecting to [::1]:55977
4572026-04-25T01:04:36.862ZApr 25 01:04:36.826 DEBG [sc] ox waiting for prompt
4582026-04-25T01:04:36.862ZApr 25 01:04:36.835 DEBG [sc] ox: logging in
4592026-04-25T01:04:36.925ZApr 25 01:04:36.913 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
4602026-04-25T01:04:36.980ZApr 25 01:04:36.969 DEBG [sc] ox: starting
4612026-04-25T01:04:36.980ZApr 25 01:04:36.969 DEBG [sc] ox: connecting to [::1]:55977
4622026-04-25T01:04:37.005ZApr 25 01:04:36.969 DEBG [sc] ox waiting for prompt
4632026-04-25T01:04:37.005ZApr 25 01:04:36.980 DEBG [sc] ox: logging in
4642026-04-25T01:04:37.068ZApr 25 01:04:37.057 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
4652026-04-25T01:04:37.135ZApr 25 01:04:37.123 DEBG [sc] ox: starting
4662026-04-25T01:04:37.135ZApr 25 01:04:37.123 DEBG [sc] ox: connecting to [::1]:55977
4672026-04-25T01:04:37.160ZApr 25 01:04:37.124 DEBG [sc] ox waiting for prompt
4682026-04-25T01:04:37.160ZApr 25 01:04:37.134 DEBG [sc] ox: logging in
4692026-04-25T01:04:37.223ZApr 25 01:04:37.212 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
4702026-04-25T01:04:37.291ZApr 25 01:04:37.279 DEBG [sc] ox: starting
4712026-04-25T01:04:37.291ZApr 25 01:04:37.280 DEBG [sc] ox: connecting to [::1]:55977
4722026-04-25T01:04:37.316ZApr 25 01:04:37.280 DEBG [sc] ox waiting for prompt
4732026-04-25T01:04:37.316ZApr 25 01:04:37.290 DEBG [sc] ox: logging in
4742026-04-25T01:04:37.390ZApr 25 01:04:37.379 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
4752026-04-25T01:04:37.462ZApr 25 01:04:37.450 INFO adding BGP router to mgd
4762026-04-25T01:04:40.530ZApr 25 01:04:40.519 INFO cr1: executing frr script show ip bgp json
4772026-04-25T01:04:40.530ZApr 25 01:04:40.519 DEBG [sc] cr1: starting
4782026-04-25T01:04:40.531ZApr 25 01:04:40.519 DEBG [sc] cr1: connecting to [::1]:54664
4792026-04-25T01:04:40.555ZApr 25 01:04:40.520 DEBG [sc] cr1 waiting for prompt
4802026-04-25T01:04:40.555ZApr 25 01:04:40.531 DEBG [sc] cr1: logging in
4812026-04-25T01:04:40.888ZApr 25 01:04:40.876 DEBG [sc] cr1: executing command `vtysh -c 'show ip bgp json'`
4822026-04-25T01:04:43.017ZApr 25 01:04:43.005 INFO cr1: executing frr script show bgp json
4832026-04-25T01:04:43.017ZApr 25 01:04:43.005 DEBG [sc] cr1: starting
4842026-04-25T01:04:43.017ZApr 25 01:04:43.005 DEBG [sc] cr1: connecting to [::1]:54664
4852026-04-25T01:04:43.042ZApr 25 01:04:43.006 DEBG [sc] cr1 waiting for prompt
4862026-04-25T01:04:43.042ZApr 25 01:04:43.016 DEBG [sc] cr1: logging in
4872026-04-25T01:04:43.160ZApr 25 01:04:43.148 DEBG [sc] cr1: executing command `vtysh -c 'show bgp json'`
4882026-04-25T01:04:45.297ZApr 25 01:04:45.285 INFO cr2: executing eos script show ip bgp | json
4892026-04-25T01:04:45.297ZApr 25 01:04:45.286 DEBG [sc] cr2: starting
4902026-04-25T01:04:45.297ZApr 25 01:04:45.286 DEBG [sc] cr2: connecting to [::1]:54726
4912026-04-25T01:04:45.322ZApr 25 01:04:45.286 DEBG [sc] cr2 waiting for prompt
4922026-04-25T01:04:45.322ZApr 25 01:04:45.297 DEBG [sc] cr2: logging in
4932026-04-25T01:04:45.642ZApr 25 01:04:45.630 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ip bgp | json'`
4942026-04-25T01:04:47.998ZApr 25 01:04:47.987 INFO cr2: executing eos script show ipv6 bgp | json
4952026-04-25T01:04:47.998ZApr 25 01:04:47.987 DEBG [sc] cr2: starting
4962026-04-25T01:04:47.998ZApr 25 01:04:47.987 DEBG [sc] cr2: connecting to [::1]:54726
4972026-04-25T01:04:48.023ZApr 25 01:04:47.987 DEBG [sc] cr2 waiting for prompt
4982026-04-25T01:04:48.023ZApr 25 01:04:47.997 DEBG [sc] cr2: logging in
4992026-04-25T01:04:48.189ZApr 25 01:04:48.177 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ipv6 bgp | json'`
5002026-04-25T01:04:50.582ZApr 25 01:04:50.570 INFO trio bgp unnumbered test passed 🎉
5012026-04-25T01:04:50.582ZApr 25 01:04:50.570 INFO destroying runner for deployment mgtriou
5022026-04-25T01:04:50.582ZApr 25 01:04:50.570 INFO destroying deployment mgtriou
5032026-04-25T01:04:50.582ZApr 25 01:04:50.570 INFO destroying nodes
5042026-04-25T01:04:50.683ZApr 25 01:04:50.672 INFO destroying links
5052026-04-25T01:04:50.683ZApr 25 01:04:50.672 INFO destroying link mgtriou_ox_sn_vnic0
5062026-04-25T01:04:50.708ZApr 25 01:04:50.674 INFO destroying link mgtriou_ox_sn_sim0
5072026-04-25T01:04:50.708ZApr 25 01:04:50.676 INFO destroying link mgtriou_cr1_vn_vnic0
5082026-04-25T01:04:51.690ZApr 25 01:04:51.679 INFO destroying link mgtriou_cr1_vn_sim0
5092026-04-25T01:04:51.715ZApr 25 01:04:51.680 INFO destroying link mgtriou_ox_sn_vnic1
5102026-04-25T01:04:51.715ZApr 25 01:04:51.681 INFO destroying link mgtriou_ox_sn_sim1
5112026-04-25T01:04:51.715ZApr 25 01:04:51.682 INFO destroying link mgtriou_cr2_vn_vnic0
5122026-04-25T01:04:51.715ZApr 25 01:04:51.683 INFO destroying link mgtriou_cr2_vn_sim0
5132026-04-25T01:04:51.715ZApr 25 01:04:51.684 INFO destroying external links
5142026-04-25T01:04:51.715ZApr 25 01:04:51.684 INFO destroying external link mgtriou_ox_vn_vnic2
5152026-04-25T01:04:51.715ZApr 25 01:04:51.686 INFO destroying external link mgtriou_cr1_vn_vnic1
5162026-04-25T01:04:51.715ZApr 25 01:04:51.687 INFO destroying external link mgtriou_cr2_vn_vnic1
5172026-04-25T01:04:51.715ZApr 25 01:04:51.688 INFO destroying images
5182026-04-25T01:04:52.165ZApr 25 01:04:52.154 INFO destroying workspace at .falcon
5192026-04-25T01:04:52.190Z+ RUST_LOG=debug
5202026-04-25T01:04:52.190Z+ pfexec ./falcon-lab run trio-bfd-static-routing
5212026-04-25T01:04:52.240ZApr 25 01:04:52.196 DEBG using default route interface igb0
5222026-04-25T01:04:52.240ZApr 25 01:04:52.196 DEBG using default route interface igb0
5232026-04-25T01:04:52.240ZApr 25 01:04:52.196 DEBG using default route interface igb0
5242026-04-25T01:04:52.240ZApr 25 01:04:52.196 INFO launching runner: deployment(mgtriobfd) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
5252026-04-25T01:04:52.240ZApr 25 01:04:52.196 INFO starting preflight for deployment mgtriobfd
5262026-04-25T01:04:52.860ZApr 25 01:04:52.848 INFO creating links
5272026-04-25T01:04:52.860ZApr 25 01:04:52.848 DEBG destroying link mgtriobfd_ox_sn_vnic0
5282026-04-25T01:04:52.884ZApr 25 01:04:52.848 DEBG destroying link mgtriobfd_ox_sn_sim0
5292026-04-25T01:04:52.884ZApr 25 01:04:52.848 INFO creating simnet link 'mgtriobfd_ox_sn_sim0'
5302026-04-25T01:04:52.884ZApr 25 01:04:52.851 INFO creating vnic link 'mgtriobfd_ox_sn_vnic0'
5312026-04-25T01:04:52.884ZApr 25 01:04:52.858 DEBG link pair created
5322026-04-25T01:04:52.885ZApr 25 01:04:52.858 DEBG destroying link mgtriobfd_cr1_vn_vnic0
5332026-04-25T01:04:52.885ZApr 25 01:04:52.858 DEBG destroying link mgtriobfd_cr1_vn_sim0
5342026-04-25T01:04:52.885ZApr 25 01:04:52.858 INFO creating simnet link 'mgtriobfd_cr1_vn_sim0'
5352026-04-25T01:04:52.885ZApr 25 01:04:52.859 INFO creating vnic link 'mgtriobfd_cr1_vn_vnic0'
5362026-04-25T01:04:52.885ZApr 25 01:04:52.866 DEBG link pair created
5372026-04-25T01:04:52.885ZApr 25 01:04:52.866 DEBG destroying link mgtriobfd_ox_sn_vnic1
5382026-04-25T01:04:52.885ZApr 25 01:04:52.866 DEBG destroying link mgtriobfd_ox_sn_sim1
5392026-04-25T01:04:52.885ZApr 25 01:04:52.866 INFO creating simnet link 'mgtriobfd_ox_sn_sim1'
5402026-04-25T01:04:52.885ZApr 25 01:04:52.867 INFO creating vnic link 'mgtriobfd_ox_sn_vnic1'
5412026-04-25T01:04:52.909ZApr 25 01:04:52.873 DEBG link pair created
5422026-04-25T01:04:52.909ZApr 25 01:04:52.873 DEBG destroying link mgtriobfd_cr2_vn_vnic0
5432026-04-25T01:04:52.909ZApr 25 01:04:52.873 DEBG destroying link mgtriobfd_cr2_vn_sim0
5442026-04-25T01:04:52.909ZApr 25 01:04:52.873 INFO creating simnet link 'mgtriobfd_cr2_vn_sim0'
5452026-04-25T01:04:52.909ZApr 25 01:04:52.875 INFO creating vnic link 'mgtriobfd_cr2_vn_vnic0'
5462026-04-25T01:04:52.909ZApr 25 01:04:52.881 DEBG link pair created
5472026-04-25T01:04:52.909ZApr 25 01:04:52.881 INFO creating external links
5482026-04-25T01:04:52.909ZApr 25 01:04:52.881 DEBG destroying external link mgtriobfd_ox_vn_vnic2
5492026-04-25T01:04:52.909ZApr 25 01:04:52.881 INFO creating external link mgtriobfd_ox_vn_vnic2
5502026-04-25T01:04:52.909ZApr 25 01:04:52.883 DEBG external link mgtriobfd_ox_vn_vnic2@igb0 created
5512026-04-25T01:04:52.910ZApr 25 01:04:52.883 DEBG destroying external link mgtriobfd_cr1_vn_vnic1
5522026-04-25T01:04:52.910ZApr 25 01:04:52.883 INFO creating external link mgtriobfd_cr1_vn_vnic1
5532026-04-25T01:04:52.910ZApr 25 01:04:52.884 DEBG external link mgtriobfd_cr1_vn_vnic1@igb0 created
5542026-04-25T01:04:52.910ZApr 25 01:04:52.884 DEBG destroying external link mgtriobfd_cr2_vn_vnic1
5552026-04-25T01:04:52.910ZApr 25 01:04:52.884 INFO creating external link mgtriobfd_cr2_vn_vnic1
5562026-04-25T01:04:52.910ZApr 25 01:04:52.885 DEBG external link mgtriobfd_cr2_vn_vnic1@igb0 created
5572026-04-25T01:04:52.910ZApr 25 01:04:52.885 INFO creating nodes
5582026-04-25T01:04:52.910ZApr 25 01:04:52.885 INFO ox: launching node
5592026-04-25T01:04:52.910ZApr 25 01:04:52.887 INFO cr1: launching node
5602026-04-25T01:04:52.910ZApr 25 01:04:52.890 INFO cr2: launching node
5612026-04-25T01:04:52.935ZApr 25 01:04:52.903 INFO launched instance ox with pid 887 on port 52516
5622026-04-25T01:04:52.935ZApr 25 01:04:52.903 INFO ox: instance ensure
5632026-04-25T01:04:52.935ZApr 25 01:04:52.904 INFO launched instance cr1 with pid 888 on port 51986
5642026-04-25T01:04:52.935ZApr 25 01:04:52.904 INFO cr1: instance ensure
5652026-04-25T01:04:52.935ZApr 25 01:04:52.904 INFO launched instance cr2 with pid 889 on port 33070
5662026-04-25T01:04:52.935ZApr 25 01:04:52.904 INFO cr2: instance ensure
5672026-04-25T01:04:55.212ZApr 25 01:04:55.200 INFO ox: instance run
5682026-04-25T01:04:55.237ZApr 25 01:04:55.201 DEBG [sc] ox: starting
5692026-04-25T01:04:55.237ZApr 25 01:04:55.201 DEBG [sc] ox: connecting to [::1]:52516
5702026-04-25T01:04:55.237ZApr 25 01:04:55.201 DEBG [sc] ox waiting for prompt
5712026-04-25T01:04:55.261ZApr 25 01:04:55.240 INFO cr2: instance run
5722026-04-25T01:04:55.261ZApr 25 01:04:55.240 DEBG [sc] cr2: starting
5732026-04-25T01:04:55.261ZApr 25 01:04:55.240 DEBG [sc] cr2: connecting to [::1]:33070
5742026-04-25T01:04:55.261ZApr 25 01:04:55.241 DEBG [sc] cr2 waiting for prompt
5752026-04-25T01:04:55.331ZApr 25 01:04:55.320 INFO cr1: instance run
5762026-04-25T01:04:55.356ZApr 25 01:04:55.320 DEBG [sc] cr1: starting
5772026-04-25T01:04:55.356ZApr 25 01:04:55.320 DEBG [sc] cr1: connecting to [::1]:51986
5782026-04-25T01:04:55.356ZApr 25 01:04:55.321 DEBG [sc] cr1 waiting for prompt
5792026-04-25T01:05:12.386ZApr 25 01:05:12.375 DEBG [sc] cr1: logging in
5802026-04-25T01:05:12.752ZApr 25 01:05:12.741 INFO cr1: mounting /opt/cargo-bay
5812026-04-25T01:05:12.753ZApr 25 01:05:12.741 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5822026-04-25T01:05:12.777ZApr 25 01:05:12.764 DEBG [sc] cr1: executing command `cd`
5832026-04-25T01:05:12.801ZApr 25 01:05:12.775 INFO cr1: finished mounting /opt/cargo-bay
5842026-04-25T01:05:12.802ZApr 25 01:05:12.775 DEBG [sc] cr1: executing command `hostname cr1`
5852026-04-25T01:05:12.802ZApr 25 01:05:12.787 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
5862026-04-25T01:05:12.826ZApr 25 01:05:12.797 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
5872026-04-25T01:05:12.826ZApr 25 01:05:12.808 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
5882026-04-25T01:05:12.850ZApr 25 01:05:12.819 INFO cr1: logging out
5892026-04-25T01:05:14.900ZApr 25 01:05:14.888 INFO cr1: logged out
5902026-04-25T01:05:15.951ZApr 25 01:05:15.940 DEBG [sc] ox: logging in
5912026-04-25T01:05:16.136ZApr 25 01:05:16.125 INFO ox: mounting /opt/cargo-bay
5922026-04-25T01:05:16.137ZApr 25 01:05:16.125 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5932026-04-25T01:05:16.853ZApr 25 01:05:16.841 DEBG [sc] cr2: logging in
5942026-04-25T01:05:17.312ZApr 25 01:05:17.300 INFO cr2: mounting /opt/cargo-bay
5952026-04-25T01:05:17.312ZApr 25 01:05:17.300 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5962026-04-25T01:05:17.336ZApr 25 01:05:17.321 DEBG [sc] cr2: executing command `cd`
5972026-04-25T01:05:17.361ZApr 25 01:05:17.333 INFO cr2: finished mounting /opt/cargo-bay
5982026-04-25T01:05:17.361ZApr 25 01:05:17.333 DEBG [sc] cr2: executing command `hostname cr2`
5992026-04-25T01:05:17.361ZApr 25 01:05:17.344 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
6002026-04-25T01:05:17.385ZApr 25 01:05:17.354 DEBG [sc] ox: executing command `cd`
6012026-04-25T01:05:17.385ZApr 25 01:05:17.355 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
6022026-04-25T01:05:17.386ZApr 25 01:05:17.365 INFO ox: finished mounting /opt/cargo-bay
6032026-04-25T01:05:17.386ZApr 25 01:05:17.365 DEBG [sc] ox: executing command `hostname ox`
6042026-04-25T01:05:17.386ZApr 25 01:05:17.366 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
6052026-04-25T01:05:17.411ZApr 25 01:05:17.376 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
6062026-04-25T01:05:17.411ZApr 25 01:05:17.377 INFO cr2: logging out
6072026-04-25T01:05:17.411ZApr 25 01:05:17.387 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
6082026-04-25T01:05:17.436ZApr 25 01:05:17.409 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
6092026-04-25T01:05:17.436ZApr 25 01:05:17.420 INFO ox: logging out
6102026-04-25T01:05:17.508ZApr 25 01:05:17.497 INFO ox: logged out
6112026-04-25T01:05:20.237ZApr 25 01:05:20.226 INFO cr2: logged out
6122026-04-25T01:05:20.262ZApr 25 01:05:20.226 DEBG [sc] ox: starting
6132026-04-25T01:05:20.262ZApr 25 01:05:20.226 DEBG [sc] ox: connecting to [::1]:52516
6142026-04-25T01:05:20.262ZApr 25 01:05:20.227 DEBG [sc] ox waiting for prompt
6152026-04-25T01:05:20.262ZApr 25 01:05:20.238 DEBG [sc] ox: logging in
6162026-04-25T01:05:20.327ZApr 25 01:05:20.315 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
6172026-04-25T01:05:25.310ZApr 25 01:05:25.298 DEBG [sc] ox: starting
6182026-04-25T01:05:25.310ZApr 25 01:05:25.298 DEBG [sc] ox: connecting to [::1]:52516
6192026-04-25T01:05:25.334ZApr 25 01:05:25.299 DEBG [sc] ox waiting for prompt
6202026-04-25T01:05:25.334ZApr 25 01:05:25.310 DEBG [sc] ox: logging in
6212026-04-25T01:05:25.397ZApr 25 01:05:25.386 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
6222026-04-25T01:05:25.475ZApr 25 01:05:25.464 DEBG [sc] ox: starting
6232026-04-25T01:05:25.475ZApr 25 01:05:25.464 DEBG [sc] ox: connecting to [::1]:52516
6242026-04-25T01:05:25.500ZApr 25 01:05:25.464 DEBG [sc] ox waiting for prompt
6252026-04-25T01:05:25.500ZApr 25 01:05:25.475 DEBG [sc] ox: logging in
6262026-04-25T01:05:25.563ZApr 25 01:05:25.552 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
6272026-04-25T01:05:25.629ZApr 25 01:05:25.617 INFO cr1: installing frr
6282026-04-25T01:05:25.629ZApr 25 01:05:25.617 INFO waiting for ceos to initialize
6292026-04-25T01:05:25.629ZApr 25 01:05:25.617 INFO ox: setting up npuvm
6302026-04-25T01:05:25.654ZApr 25 01:05:25.617 DEBG [sc] cr2: starting
6312026-04-25T01:05:25.654ZApr 25 01:05:25.617 DEBG [sc] cr2: connecting to [::1]:33070
6322026-04-25T01:05:25.654ZApr 25 01:05:25.617 DEBG [sc] cr1: starting
6332026-04-25T01:05:25.654ZApr 25 01:05:25.617 DEBG [sc] cr1: connecting to [::1]:51986
6342026-04-25T01:05:25.654ZApr 25 01:05:25.617 DEBG [sc] ox: starting
6352026-04-25T01:05:25.654ZApr 25 01:05:25.617 DEBG [sc] ox: connecting to [::1]:52516
6362026-04-25T01:05:25.654ZApr 25 01:05:25.618 DEBG [sc] cr1 waiting for prompt
6372026-04-25T01:05:25.654ZApr 25 01:05:25.618 DEBG [sc] cr2 waiting for prompt
6382026-04-25T01:05:25.654ZApr 25 01:05:25.618 DEBG [sc] ox waiting for prompt
6392026-04-25T01:05:25.654ZApr 25 01:05:25.628 DEBG [sc] ox: logging in
6402026-04-25T01:05:25.654ZApr 25 01:05:25.629 DEBG [sc] cr1: logging in
6412026-04-25T01:05:25.654ZApr 25 01:05:25.629 DEBG [sc] cr2: logging in
6422026-04-25T01:05:25.717ZApr 25 01:05:25.705 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
6432026-04-25T01:05:25.773ZApr 25 01:05:25.761 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6442026-04-25T01:05:25.991ZApr 25 01:05:25.979 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
6452026-04-25T01:05:28.011ZApr 25 01:05:27.998 INFO cr2: executing eos script show version
6462026-04-25T01:05:28.011ZApr 25 01:05:27.998 DEBG [sc] cr2: starting
6472026-04-25T01:05:28.011ZApr 25 01:05:27.998 DEBG [sc] cr2: connecting to [::1]:33070
6482026-04-25T01:05:28.037ZApr 25 01:05:27.998 DEBG [sc] cr2 waiting for prompt
6492026-04-25T01:05:28.037ZApr 25 01:05:28.010 DEBG [sc] cr2: logging in
6502026-04-25T01:05:28.164ZApr 25 01:05:28.153 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6512026-04-25T01:05:31.236ZApr 25 01:05:31.224 DEBG [sc] ox: starting
6522026-04-25T01:05:31.236ZApr 25 01:05:31.224 DEBG [sc] ox: connecting to [::1]:52516
6532026-04-25T01:05:31.260ZApr 25 01:05:31.225 DEBG [sc] ox waiting for prompt
6542026-04-25T01:05:31.261ZApr 25 01:05:31.236 DEBG [sc] ox: logging in
6552026-04-25T01:05:31.324ZApr 25 01:05:31.312 DEBG [sc] ox: executing command `chmod +x npuvm`
6562026-04-25T01:05:31.391ZApr 25 01:05:31.380 DEBG [sc] ox: starting
6572026-04-25T01:05:31.391ZApr 25 01:05:31.380 DEBG [sc] ox: connecting to [::1]:52516
6582026-04-25T01:05:31.416ZApr 25 01:05:31.380 DEBG [sc] ox waiting for prompt
6592026-04-25T01:05:31.416ZApr 25 01:05:31.391 DEBG [sc] ox: logging in
6602026-04-25T01:05:31.479ZApr 25 01:05:31.468 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
6612026-04-25T01:05:37.708ZApr 25 01:05:37.697 DEBG [sc] cr2: starting
6622026-04-25T01:05:37.708ZApr 25 01:05:37.697 DEBG [sc] cr2: connecting to [::1]:33070
6632026-04-25T01:05:37.709ZApr 25 01:05:37.697 DEBG [sc] cr2 waiting for prompt
6642026-04-25T01:05:37.733ZApr 25 01:05:37.708 DEBG [sc] cr2: logging in
6652026-04-25T01:05:37.874ZApr 25 01:05:37.863 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6662026-04-25T01:05:39.983ZApr 25 01:05:39.971 INFO cr2: executing eos script show version
6672026-04-25T01:05:39.983ZApr 25 01:05:39.971 DEBG [sc] cr2: starting
6682026-04-25T01:05:39.983ZApr 25 01:05:39.971 DEBG [sc] cr2: connecting to [::1]:33070
6692026-04-25T01:05:40.007ZApr 25 01:05:39.972 DEBG [sc] cr2 waiting for prompt
6702026-04-25T01:05:40.007ZApr 25 01:05:39.982 DEBG [sc] cr2: logging in
6712026-04-25T01:05:40.159ZApr 25 01:05:40.147 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6722026-04-25T01:06:03.593ZApr 25 01:06:03.582 INFO cr1: enabling frr daemon bfdd
6732026-04-25T01:06:03.593ZApr 25 01:06:03.582 DEBG [sc] cr1: starting
6742026-04-25T01:06:03.593ZApr 25 01:06:03.582 DEBG [sc] cr1: connecting to [::1]:51986
6752026-04-25T01:06:03.618ZApr 25 01:06:03.583 DEBG [sc] cr1 waiting for prompt
6762026-04-25T01:06:03.618ZApr 25 01:06:03.593 DEBG [sc] cr1: logging in
6772026-04-25T01:06:03.737ZApr 25 01:06:03.726 DEBG [sc] cr1: executing command `sed -i 's/bfdd=no/bfdd=yes/g' /etc/frr/daemons`
6782026-04-25T01:06:05.821ZApr 25 01:06:05.809 DEBG [sc] cr1: starting
6792026-04-25T01:06:05.821ZApr 25 01:06:05.809 DEBG [sc] cr1: connecting to [::1]:51986
6802026-04-25T01:06:05.845ZApr 25 01:06:05.810 DEBG [sc] cr1 waiting for prompt
6812026-04-25T01:06:05.845ZApr 25 01:06:05.821 DEBG [sc] cr1: logging in
6822026-04-25T01:06:05.975ZApr 25 01:06:05.964 DEBG [sc] cr1: executing command `systemctl restart frr`
6832026-04-25T01:06:13.557ZApr 25 01:06:13.545 INFO cr1: executing frr script
6842026-04-25T01:06:13.557Z configure
6852026-04-25T01:06:13.557Z interface enp0s8
6862026-04-25T01:06:13.557Z ip address 10.0.0.2/24
6872026-04-25T01:06:13.557Z ipv6 address fd00:1::2/64
6882026-04-25T01:06:13.557Z no shutdown
6892026-04-25T01:06:13.557Z exit
6902026-04-25T01:06:13.557Z bfd
6912026-04-25T01:06:13.557Z peer 10.0.0.1 local-address 10.0.0.2
6922026-04-25T01:06:13.557Z detect-multiplier 3
6932026-04-25T01:06:13.557Z receive-interval 300
6942026-04-25T01:06:13.557Z transmit-interval 300
6952026-04-25T01:06:13.557Z no shutdown
6962026-04-25T01:06:13.557Z exit
6972026-04-25T01:06:13.557Z peer fd00:1::1 local-address fd00:1::2
6982026-04-25T01:06:13.557Z detect-multiplier 3
6992026-04-25T01:06:13.557Z receive-interval 300
7002026-04-25T01:06:13.558Z transmit-interval 300
7012026-04-25T01:06:13.558Z no shutdown
7022026-04-25T01:06:13.558Z exit
7032026-04-25T01:06:13.558Z exit
7042026-04-25T01:06:13.558Z
7052026-04-25T01:06:13.558ZApr 25 01:06:13.546 DEBG [sc] cr1: starting
7062026-04-25T01:06:13.558ZApr 25 01:06:13.546 DEBG [sc] cr1: connecting to [::1]:51986
7072026-04-25T01:06:13.583ZApr 25 01:06:13.546 DEBG [sc] cr1 waiting for prompt
7082026-04-25T01:06:13.583ZApr 25 01:06:13.557 DEBG [sc] cr1: logging in
7092026-04-25T01:06:13.700ZApr 25 01:06:13.689 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 ' '`
7102026-04-25T01:07:17.784ZApr 25 01:07:17.773 DEBG [sc] ox: starting
7112026-04-25T01:07:17.784ZApr 25 01:07:17.773 DEBG [sc] ox: connecting to [::1]:52516
7122026-04-25T01:07:17.809ZApr 25 01:07:17.773 DEBG [sc] ox waiting for prompt
7132026-04-25T01:07:17.809ZApr 25 01:07:17.784 DEBG [sc] ox: logging in
7142026-04-25T01:07:17.873ZApr 25 01:07:17.861 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
7152026-04-25T01:07:17.994ZApr 25 01:07:17.982 INFO destroying runner for deployment mgtriobfd
7162026-04-25T01:07:17.994ZApr 25 01:07:17.982 INFO destroying deployment mgtriobfd
7172026-04-25T01:07:17.994ZApr 25 01:07:17.982 INFO destroying nodes
7182026-04-25T01:07:18.036ZApr 25 01:07:18.025 INFO destroying links
7192026-04-25T01:07:18.036ZApr 25 01:07:18.025 INFO destroying link mgtriobfd_ox_sn_vnic0
7202026-04-25T01:07:18.061ZApr 25 01:07:18.027 INFO destroying link mgtriobfd_ox_sn_sim0
7212026-04-25T01:07:18.061ZApr 25 01:07:18.028 INFO destroying link mgtriobfd_cr1_vn_vnic0
7222026-04-25T01:07:19.043ZApr 25 01:07:19.031 INFO destroying link mgtriobfd_cr1_vn_sim0
7232026-04-25T01:07:19.067ZApr 25 01:07:19.032 INFO destroying link mgtriobfd_ox_sn_vnic1
7242026-04-25T01:07:19.067ZApr 25 01:07:19.033 INFO destroying link mgtriobfd_ox_sn_sim1
7252026-04-25T01:07:19.067ZApr 25 01:07:19.034 INFO destroying link mgtriobfd_cr2_vn_vnic0
7262026-04-25T01:07:19.067ZApr 25 01:07:19.035 INFO destroying link mgtriobfd_cr2_vn_sim0
7272026-04-25T01:07:19.067ZApr 25 01:07:19.036 INFO destroying external links
7282026-04-25T01:07:19.067ZApr 25 01:07:19.036 INFO destroying external link mgtriobfd_ox_vn_vnic2
7292026-04-25T01:07:19.067ZApr 25 01:07:19.037 INFO destroying external link mgtriobfd_cr1_vn_vnic1
7302026-04-25T01:07:19.067ZApr 25 01:07:19.038 INFO destroying external link mgtriobfd_cr2_vn_vnic1
7312026-04-25T01:07:19.067ZApr 25 01:07:19.039 INFO destroying images
7322026-04-25T01:07:19.555ZApr 25 01:07:19.543 INFO destroying workspace at .falcon
7332026-04-25T01:07:19.580ZError: exec: [sc] cr2: timeout waiting for data
7342026-04-25T01:07:19.580Zprocess exited: duration 639668 ms, exit code 1
 
7352026-04-25T01:07:19.631Zfound 0 output files