01KRY8N9T4P36XRZPA7HFAZDJY: falcon

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

Buildomat Job: 01KRY8NPCJ8VF0NE125YW2M7Z5

Tags:

Output:

SEQ GLOBAL TIME DETAILS
12026-05-18T19:36:53.646Zjob dependencies complete; ready to run (waiting for 13 m 40 s)
22026-05-18T19:40:12.114Zjob assigned to worker 01KRY9ER960TH852CHBZ9BT718 [factory edgar, gimlet/BRM42220010/967] (queued for 3 m 18 s)
32026-05-18T19:40:12.904Zdownloading input: /input/build/work/debug/ddmadm
42026-05-18T19:40:35.854Zdownloaded input: /input/build/work/debug/ddmadm
52026-05-18T19:40:35.854Zdownloading input: /input/build/work/debug/ddmd
62026-05-18T19:41:03.038Zdownloaded input: /input/build/work/debug/ddmd
72026-05-18T19:41:03.063Zdownloading input: /input/build-interop/work/testbed.tar.gz
82026-05-18T19:41:12.017Zdownloaded input: /input/build-interop/work/testbed.tar.gz
92026-05-18T19:41:12.017Zdownloading input: /input/build-interop/work/dhcp-server
102026-05-18T19:41:14.529Zdownloaded input: /input/build-interop/work/dhcp-server
112026-05-18T19:41:14.529Zdownloading input: /input/build/work/debug/mgadm
122026-05-18T19:41:41.151Zdownloaded input: /input/build/work/debug/mgadm
132026-05-18T19:41:41.151Zdownloading input: /input/build/work/debug/mgd
142026-05-18T19:42:11.869Zdownloaded input: /input/build/work/debug/mgd
152026-05-18T19:42:11.893Zdownloading input: /input/build/work/release/ddmadm
162026-05-18T19:42:14.170Zdownloaded input: /input/build/work/release/ddmadm
172026-05-18T19:42:14.170Zdownloading input: /input/build/work/release/ddmd
182026-05-18T19:42:16.846Zdownloaded input: /input/build/work/release/ddmd
192026-05-18T19:42:16.846Zdownloading input: /input/build/work/release/falcon-lab
202026-05-18T19:42:20.142Zdownloaded input: /input/build/work/release/falcon-lab
212026-05-18T19:42:20.142Zdownloading input: /input/build/work/release/mgadm
222026-05-18T19:42:22.805Zdownloaded input: /input/build/work/release/mgadm
232026-05-18T19:42:22.805Zdownloading input: /input/build/work/release/mgd
242026-05-18T19:42:26.178Zdownloaded input: /input/build/work/release/mgd
 
252026-05-18T19:42:26.178Zstarting task 0: "setup"
262026-05-18T19:42:26.203Z++ uname -s
272026-05-18T19:42:26.203Z+ kern=SunOS
282026-05-18T19:42:26.203Z+ build_user=build
292026-05-18T19:42:26.203Z+ build_uid=12345
302026-05-18T19:42:26.203Z+ work_dir=/work
312026-05-18T19:42:26.203Z+ input_dir=/input
322026-05-18T19:42:26.203Z+ [[ 0 == 12345 ]]
332026-05-18T19:42:26.203Z+ case "$kern" in
342026-05-18T19:42:26.203Z+ groupadd -g 12345 build
352026-05-18T19:42:26.228Z+ useradd -u 12345 -g build -d /home/build -s /bin/bash -c build -P 'Primary Administrator' build
362026-05-18T19:42:28.217Z+ zfs create -o mountpoint=/work rpool/work
372026-05-18T19:42:28.477Z++ awk '$2 == "/home" { print $3 }' /etc/mnttab
382026-05-18T19:42:28.502Z+ home_fs=
392026-05-18T19:42:28.502Z+ [[ '' == autofs ]]
402026-05-18T19:42:28.502Z+ mkdir -p /home/build
412026-05-18T19:42:28.502Z+ chown build:build /home/build /work
422026-05-18T19:42:30.492Z+ chmod 0700 /home/build /work
432026-05-18T19:42:30.516Zprocess exited: duration 4316 ms, exit code 0
 
442026-05-18T19:42:30.564Zstarting task 1: "authentication"
452026-05-18T19:42:30.661Zprocess exited: duration 96 ms, exit code 0
 
462026-05-18T19:42:30.710Zstarting task 2: "build"
472026-05-18T19:42:30.734Z+ set -e
482026-05-18T19:42:30.734Z+ banner zpool
492026-05-18T19:42:30.734Z
502026-05-18T19:42:30.734Z ###### ##### #### #### #
512026-05-18T19:42:30.734Z # # # # # # # #
522026-05-18T19:42:30.734Z # # # # # # # #
532026-05-18T19:42:30.734Z # ##### # # # # #
542026-05-18T19:42:30.734Z # # # # # # #
552026-05-18T19:42:30.734Z ###### # #### #### ######
562026-05-18T19:42:30.734Z
572026-05-18T19:42:30.734Z++ pfexec diskinfo -pH
582026-05-18T19:42:30.758Z++ sort -k8 -n -r
592026-05-18T19:42:30.758Z++ head -1
602026-05-18T19:42:30.759Z++ awk '{print $2}'
612026-05-18T19:42:30.783Z+ DISK=c9t0014EE81000BC3B1d0
622026-05-18T19:42:30.783Z+ export DISK
632026-05-18T19:42:30.783Z+ pfexec zpool create -o ashift=12 -f cpool c9t0014EE81000BC3B1d0
642026-05-18T19:42:30.848Z+ pfexec zfs create -o mountpoint=/ci cpool/ci
652026-05-18T19:42:30.875Z++ curl -s http://catacomb.eng.oxide.computer:12346/trim-me
662026-05-18T19:42:31.031Z+ [[ true =~ true ]]
672026-05-18T19:42:31.031Z+ pfexec zpool trim cpool
682026-05-18T19:42:31.055Z++ zpool status -t cpool
692026-05-18T19:42:31.081Z+ [[ ! pool: cpool
702026-05-18T19:42:31.081Z state: ONLINE
712026-05-18T19:42:31.081Z scan: none requested
722026-05-18T19:42:31.081Zconfig:
732026-05-18T19:42:31.081Z
742026-05-18T19:42:31.081Z NAME STATE READ WRITE CKSUM
752026-05-18T19:42:31.081Z cpool ONLINE 0 0 0
762026-05-18T19:42:31.081Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (1% trimmed, started at May 18, 2026 at 07:42:31 PM UTC)
772026-05-18T19:42:31.081Z
782026-05-18T19:42:31.081Zerrors: No known data errors =~ 100% ]]
792026-05-18T19:42:31.081Z+ sleep 10
802026-05-18T19:42:41.065Z++ zpool status -t cpool
812026-05-18T19:42:41.097Z+ [[ ! pool: cpool
822026-05-18T19:42:41.097Z state: ONLINE
832026-05-18T19:42:41.097Z scan: none requested
842026-05-18T19:42:41.097Zconfig:
852026-05-18T19:42:41.097Z
862026-05-18T19:42:41.097Z NAME STATE READ WRITE CKSUM
872026-05-18T19:42:41.097Z cpool ONLINE 0 0 0
882026-05-18T19:42:41.097Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (71% trimmed, started at May 18, 2026 at 07:42:31 PM UTC)
892026-05-18T19:42:41.097Z
902026-05-18T19:42:41.097Zerrors: No known data errors =~ 100% ]]
912026-05-18T19:42:41.097Z+ sleep 10
922026-05-18T19:42:51.080Z++ zpool status -t cpool
932026-05-18T19:42:51.104Z+ [[ ! pool: cpool
942026-05-18T19:42:51.104Z state: ONLINE
952026-05-18T19:42:51.104Z scan: none requested
962026-05-18T19:42:51.104Zconfig:
972026-05-18T19:42:51.104Z
982026-05-18T19:42:51.104Z NAME STATE READ WRITE CKSUM
992026-05-18T19:42:51.104Z cpool ONLINE 0 0 0
1002026-05-18T19:42:51.104Z c9t0014EE81000BC3B1d0 ONLINE 0 0 0 (100% trimmed, completed at May 18, 2026 at 07:42:45 PM UTC)
1012026-05-18T19:42:51.104Z
1022026-05-18T19:42:51.104Zerrors: No known data errors =~ 100% ]]
1032026-05-18T19:42:51.104Z+ pfexec chown 12345 /ci
1042026-05-18T19:42:51.104Z+ cd /ci
1052026-05-18T19:42:51.105Z+ export FALCON_DATASET=cpool/falcon
1062026-05-18T19:42:51.105Z+ FALCON_DATASET=cpool/falcon
1072026-05-18T19:42:51.105Z+ banner setup
1082026-05-18T19:42:51.105Z
1092026-05-18T19:42:51.105Z #### ###### ##### # # #####
1102026-05-18T19:42:51.105Z # # # # # # #
1112026-05-18T19:42:51.105Z #### ##### # # # # #
1122026-05-18T19:42:51.105Z # # # # # #####
1132026-05-18T19:42:51.105Z # # # # # # #
1142026-05-18T19:42:51.105Z #### ###### # #### #
1152026-05-18T19:42:51.105Z
1162026-05-18T19:42:51.105Z+ cp /input/build-interop/work/dhcp-server .
1172026-05-18T19:42:51.457Z+ cp /input/build/work/release/falcon-lab .
1182026-05-18T19:42:51.523Z+ cp /input/build/work/release/mgd .
1192026-05-18T19:42:51.588Z+ cp /input/build/work/release/ddmd .
1202026-05-18T19:42:51.660Z+ chmod +x dhcp-server falcon-lab mgd ddmd
1212026-05-18T19:42:51.686Z+ mkdir -p cargo-bay
1222026-05-18T19:42:51.686Z+ mv mgd cargo-bay/
1232026-05-18T19:42:51.686Z+ mv ddmd cargo-bay/
1242026-05-18T19:42:51.686Z+ export EXT_INTERFACE=igb0
1252026-05-18T19:42:51.686Z+ EXT_INTERFACE=igb0
1262026-05-18T19:42:51.686Z++ bmat address ls -f extra -Ho first
1272026-05-18T19:42:51.711Z+ first=10.151.6.164
1282026-05-18T19:42:51.711Z++ bmat address ls -f extra -Ho last
1292026-05-18T19:42:51.735Z+ last=10.151.6.227
1302026-05-18T19:42:51.735Z++ bmat address ls -f extra -Ho gateway
1312026-05-18T19:42:51.759Z+ gw=10.151.6.1
1322026-05-18T19:42:51.759Z++ ipadm show-addr igb0/dhcp -po ADDR
1332026-05-18T19:42:51.783Z++ sed 's#/.*##g'
1342026-05-18T19:42:51.783Z+ server=10.151.6.100
1352026-05-18T19:42:51.783Z+ RUST_LOG=debug
1362026-05-18T19:42:51.784Z+ pfexec ./falcon-lab run trio-unnumbered
1372026-05-18T19:42:51.784Z+ pfexec ./dhcp-server 10.151.6.164 10.151.6.227 10.151.6.1 10.151.6.100
1382026-05-18T19:42:51.809ZMay 18 19:42:51.780 DEBG using default route interface igb0
1392026-05-18T19:42:51.809ZMay 18 19:42:51.781 DEBG using default route interface igb0
1402026-05-18T19:42:51.809ZMay 18 19:42:51.781 DEBG using default route interface igb0
1412026-05-18T19:42:51.809ZMay 18 19:42:51.781 INFO launching runner: deployment(mgtriou) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
1422026-05-18T19:42:51.809ZMay 18 19:42:51.781 INFO starting preflight for deployment mgtriou
1432026-05-18T19:42:51.809ZMay 18 19:42:51.781 INFO propolis-server binary not found
1442026-05-18T19:42:51.809ZMay 18 19:42:51.781 INFO downloading propolis server rev 36f20be9bb4c3b362029237f5feb6377c982395f, writing to .falcon/bin/propolis-server
1452026-05-18T19:42:55.763ZMay 18 19:42:55.755 INFO ovmf fd not found
1462026-05-18T19:42:55.763ZMay 18 19:42:55.755 INFO downloading ovmf
1472026-05-18T19:42:56.129ZMay 18 19:42:56.121 INFO base image for helios-2.9 does not exist, attempting to install
1482026-05-18T19:42:56.129ZMay 18 19:42:56.121 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/helios-2.9_0.raw.xz
1492026-05-18T19:43:24.985ZMay 18 19:43:24.981 INFO extracting image to /tmp/helios-2.9_0.raw
1502026-05-18T19:43:59.012ZMay 18 19:43:59.010 INFO creating zvol cpool/falcon/img/helios-2.9 of size 4508880896
1512026-05-18T19:43:59.059ZMay 18 19:43:59.058 INFO copying image data to zvol
1522026-05-18T19:44:09.318ZMay 18 19:44:09.318 INFO creating zfs snapshot cpool/falcon/img/helios-2.9@base
1532026-05-18T19:44:12.766ZMay 18 19:44:12.766 INFO base image for debian-13.2 does not exist, attempting to install
1542026-05-18T19:44:12.766ZMay 18 19:44:12.766 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/debian-13.2_0.raw.xz
1552026-05-18T19:44:34.142ZMay 18 19:44:34.139 INFO extracting image to /tmp/debian-13.2_0.raw
1562026-05-18T19:44:55.504ZMay 18 19:44:55.504 INFO creating zvol cpool/falcon/img/debian-13.2 of size 3221229568
1572026-05-18T19:44:55.530ZMay 18 19:44:55.530 INFO copying image data to zvol
1582026-05-18T19:45:01.761ZMay 18 19:45:01.761 INFO creating zfs snapshot cpool/falcon/img/debian-13.2@base
1592026-05-18T19:45:05.102ZMay 18 19:45:05.103 INFO base image for eos-4.35 does not exist, attempting to install
1602026-05-18T19:45:05.102ZMay 18 19:45:05.103 INFO trying to download https://oxide-falcon-assets.s3.us-west-2.amazonaws.com/eos-4.35_0.raw.xz
1612026-05-18T19:45:48.810ZMay 18 19:45:48.808 INFO extracting image to /tmp/eos-4.35_0.raw
1622026-05-18T19:47:13.399ZMay 18 19:47:13.387 INFO creating zvol cpool/falcon/img/eos-4.35 of size 21474840576
1632026-05-18T19:47:13.423ZMay 18 19:47:13.412 INFO copying image data to zvol
1642026-05-18T19:48:02.118ZMay 18 19:48:02.107 INFO creating zfs snapshot cpool/falcon/img/eos-4.35@base
1652026-05-18T19:48:05.457ZMay 18 19:48:05.447 INFO creating links
1662026-05-18T19:48:05.457ZMay 18 19:48:05.447 DEBG destroying link mgtriou_ox_sn_vnic0
1672026-05-18T19:48:05.481ZMay 18 19:48:05.447 DEBG destroying link mgtriou_ox_sn_sim0
1682026-05-18T19:48:05.481ZMay 18 19:48:05.447 INFO creating simnet link 'mgtriou_ox_sn_sim0'
1692026-05-18T19:48:05.481ZMay 18 19:48:05.449 INFO creating vnic link 'mgtriou_ox_sn_vnic0'
1702026-05-18T19:48:05.481ZMay 18 19:48:05.456 DEBG link pair created
1712026-05-18T19:48:05.481ZMay 18 19:48:05.456 DEBG destroying link mgtriou_cr1_vn_vnic0
1722026-05-18T19:48:05.481ZMay 18 19:48:05.456 DEBG destroying link mgtriou_cr1_vn_sim0
1732026-05-18T19:48:05.481ZMay 18 19:48:05.456 INFO creating simnet link 'mgtriou_cr1_vn_sim0'
1742026-05-18T19:48:05.482ZMay 18 19:48:05.457 INFO creating vnic link 'mgtriou_cr1_vn_vnic0'
1752026-05-18T19:48:05.482ZMay 18 19:48:05.463 DEBG link pair created
1762026-05-18T19:48:05.482ZMay 18 19:48:05.464 DEBG destroying link mgtriou_ox_sn_vnic1
1772026-05-18T19:48:05.482ZMay 18 19:48:05.464 DEBG destroying link mgtriou_ox_sn_sim1
1782026-05-18T19:48:05.482ZMay 18 19:48:05.464 INFO creating simnet link 'mgtriou_ox_sn_sim1'
1792026-05-18T19:48:05.482ZMay 18 19:48:05.465 INFO creating vnic link 'mgtriou_ox_sn_vnic1'
1802026-05-18T19:48:05.506ZMay 18 19:48:05.472 DEBG link pair created
1812026-05-18T19:48:05.506ZMay 18 19:48:05.472 DEBG destroying link mgtriou_cr2_vn_vnic0
1822026-05-18T19:48:05.506ZMay 18 19:48:05.472 DEBG destroying link mgtriou_cr2_vn_sim0
1832026-05-18T19:48:05.506ZMay 18 19:48:05.472 INFO creating simnet link 'mgtriou_cr2_vn_sim0'
1842026-05-18T19:48:05.506ZMay 18 19:48:05.474 INFO creating vnic link 'mgtriou_cr2_vn_vnic0'
1852026-05-18T19:48:05.506ZMay 18 19:48:05.481 DEBG link pair created
1862026-05-18T19:48:05.506ZMay 18 19:48:05.481 INFO creating external links
1872026-05-18T19:48:05.506ZMay 18 19:48:05.481 DEBG destroying external link mgtriou_ox_vn_vnic2
1882026-05-18T19:48:05.506ZMay 18 19:48:05.481 INFO creating external link mgtriou_ox_vn_vnic2
1892026-05-18T19:48:05.506ZMay 18 19:48:05.483 DEBG external link mgtriou_ox_vn_vnic2@igb0 created
1902026-05-18T19:48:05.506ZMay 18 19:48:05.483 DEBG destroying external link mgtriou_cr1_vn_vnic1
1912026-05-18T19:48:05.506ZMay 18 19:48:05.483 INFO creating external link mgtriou_cr1_vn_vnic1
1922026-05-18T19:48:05.506ZMay 18 19:48:05.485 DEBG external link mgtriou_cr1_vn_vnic1@igb0 created
1932026-05-18T19:48:05.506ZMay 18 19:48:05.485 DEBG destroying external link mgtriou_cr2_vn_vnic1
1942026-05-18T19:48:05.507ZMay 18 19:48:05.485 INFO creating external link mgtriou_cr2_vn_vnic1
1952026-05-18T19:48:05.507ZMay 18 19:48:05.486 DEBG external link mgtriou_cr2_vn_vnic1@igb0 created
1962026-05-18T19:48:05.507ZMay 18 19:48:05.486 INFO creating nodes
1972026-05-18T19:48:05.507ZMay 18 19:48:05.486 INFO ox: launching node
1982026-05-18T19:48:05.507ZMay 18 19:48:05.489 INFO cr1: launching node
1992026-05-18T19:48:05.507ZMay 18 19:48:05.491 INFO cr2: launching node
2002026-05-18T19:48:05.531ZMay 18 19:48:05.504 INFO launched instance ox with pid 855 on port 61581
2012026-05-18T19:48:05.531ZMay 18 19:48:05.504 INFO ox: instance ensure
2022026-05-18T19:48:05.531ZMay 18 19:48:05.505 INFO launched instance cr1 with pid 856 on port 32814
2032026-05-18T19:48:05.531ZMay 18 19:48:05.505 INFO cr1: instance ensure
2042026-05-18T19:48:05.531ZMay 18 19:48:05.505 INFO launched instance cr2 with pid 857 on port 34930
2052026-05-18T19:48:05.531ZMay 18 19:48:05.505 INFO cr2: instance ensure
2062026-05-18T19:48:07.859ZMay 18 19:48:07.848 INFO cr2: instance ensure completed after 0 retries
2072026-05-18T19:48:07.859ZMay 18 19:48:07.848 INFO cr2: instance run
2082026-05-18T19:48:07.909ZMay 18 19:48:07.849 DEBG [sc] cr2: starting
2092026-05-18T19:48:07.909ZMay 18 19:48:07.849 DEBG [sc] cr2: connecting to [::1]:34930
2102026-05-18T19:48:07.909ZMay 18 19:48:07.850 DEBG [sc] cr2 waiting for prompt
2112026-05-18T19:48:07.934ZMay 18 19:48:07.924 INFO ox: instance ensure completed after 0 retries
2122026-05-18T19:48:07.935ZMay 18 19:48:07.924 INFO ox: instance run
2132026-05-18T19:48:07.959ZMay 18 19:48:07.925 DEBG [sc] ox: starting
2142026-05-18T19:48:07.959ZMay 18 19:48:07.925 DEBG [sc] ox: connecting to [::1]:61581
2152026-05-18T19:48:07.959ZMay 18 19:48:07.925 DEBG [sc] ox waiting for prompt
2162026-05-18T19:48:07.959ZMay 18 19:48:07.937 INFO cr1: instance ensure completed after 0 retries
2172026-05-18T19:48:07.959ZMay 18 19:48:07.937 INFO cr1: instance run
2182026-05-18T19:48:07.959ZMay 18 19:48:07.938 DEBG [sc] cr1: starting
2192026-05-18T19:48:07.959ZMay 18 19:48:07.938 DEBG [sc] cr1: connecting to [::1]:32814
2202026-05-18T19:48:07.959ZMay 18 19:48:07.938 DEBG [sc] cr1 waiting for prompt
2212026-05-18T19:48:25.066ZMay 18 19:48:25.055 DEBG [sc] cr1: logging in
2222026-05-18T19:48:25.431ZMay 18 19:48:25.420 INFO cr1: mounting /opt/cargo-bay
2232026-05-18T19:48:25.431ZMay 18 19:48:25.420 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2242026-05-18T19:48:25.455ZMay 18 19:48:25.443 DEBG [sc] cr1: executing command `cd`
2252026-05-18T19:48:25.479ZMay 18 19:48:25.454 INFO cr1: finished mounting /opt/cargo-bay
2262026-05-18T19:48:25.479ZMay 18 19:48:25.454 DEBG [sc] cr1: executing command `hostname cr1`
2272026-05-18T19:48:25.479ZMay 18 19:48:25.465 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
2282026-05-18T19:48:25.503ZMay 18 19:48:25.476 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
2292026-05-18T19:48:25.503ZMay 18 19:48:25.487 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
2302026-05-18T19:48:25.527ZMay 18 19:48:25.498 INFO cr1: logging out
2312026-05-18T19:48:27.573ZMay 18 19:48:27.563 INFO cr1: logged out
2322026-05-18T19:48:28.522ZMay 18 19:48:28.510 DEBG [sc] ox: logging in
2332026-05-18T19:48:28.691ZMay 18 19:48:28.680 INFO ox: mounting /opt/cargo-bay
2342026-05-18T19:48:28.691ZMay 18 19:48:28.680 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2352026-05-18T19:48:29.582ZMay 18 19:48:29.570 DEBG [sc] cr2: logging in
2362026-05-18T19:48:30.040ZMay 18 19:48:30.029 INFO cr2: mounting /opt/cargo-bay
2372026-05-18T19:48:30.040ZMay 18 19:48:30.030 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
2382026-05-18T19:48:30.065ZMay 18 19:48:30.052 DEBG [sc] cr2: executing command `cd`
2392026-05-18T19:48:30.088ZMay 18 19:48:30.063 INFO cr2: finished mounting /opt/cargo-bay
2402026-05-18T19:48:30.089ZMay 18 19:48:30.063 DEBG [sc] cr2: executing command `hostname cr2`
2412026-05-18T19:48:30.089ZMay 18 19:48:30.073 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
2422026-05-18T19:48:30.113ZMay 18 19:48:30.084 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
2432026-05-18T19:48:30.113ZMay 18 19:48:30.096 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
2442026-05-18T19:48:30.137ZMay 18 19:48:30.107 INFO cr2: logging out
2452026-05-18T19:48:30.236ZMay 18 19:48:30.225 DEBG [sc] ox: executing command `cd`
2462026-05-18T19:48:30.260ZMay 18 19:48:30.236 INFO ox: finished mounting /opt/cargo-bay
2472026-05-18T19:48:30.260ZMay 18 19:48:30.236 DEBG [sc] ox: executing command `hostname ox`
2482026-05-18T19:48:30.260ZMay 18 19:48:30.248 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
2492026-05-18T19:48:30.284ZMay 18 19:48:30.258 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
2502026-05-18T19:48:30.284ZMay 18 19:48:30.269 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
2512026-05-18T19:48:30.308ZMay 18 19:48:30.280 INFO ox: logging out
2522026-05-18T19:48:30.357ZMay 18 19:48:30.346 INFO ox: logged out
2532026-05-18T19:48:32.997ZMay 18 19:48:32.986 INFO cr2: logged out
2542026-05-18T19:48:33.021ZMay 18 19:48:32.986 DEBG [sc] ox: starting
2552026-05-18T19:48:33.021ZMay 18 19:48:32.986 DEBG [sc] ox: connecting to [::1]:61581
2562026-05-18T19:48:33.021ZMay 18 19:48:32.987 DEBG [sc] ox waiting for prompt
2572026-05-18T19:48:33.021ZMay 18 19:48:32.998 DEBG [sc] ox: logging in
2582026-05-18T19:48:33.097ZMay 18 19:48:33.086 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
2592026-05-18T19:48:39.450ZMay 18 19:48:39.439 DEBG [sc] ox: starting
2602026-05-18T19:48:39.450ZMay 18 19:48:39.439 DEBG [sc] ox: connecting to [::1]:61581
2612026-05-18T19:48:39.474ZMay 18 19:48:39.440 DEBG [sc] ox waiting for prompt
2622026-05-18T19:48:39.474ZMay 18 19:48:39.450 DEBG [sc] ox: logging in
2632026-05-18T19:48:39.539ZMay 18 19:48:39.527 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
2642026-05-18T19:48:39.627ZMay 18 19:48:39.616 DEBG [sc] ox: starting
2652026-05-18T19:48:39.627ZMay 18 19:48:39.616 DEBG [sc] ox: connecting to [::1]:61581
2662026-05-18T19:48:39.651ZMay 18 19:48:39.616 DEBG [sc] ox waiting for prompt
2672026-05-18T19:48:39.651ZMay 18 19:48:39.626 DEBG [sc] ox: logging in
2682026-05-18T19:48:39.726ZMay 18 19:48:39.714 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
2692026-05-18T19:48:39.792ZMay 18 19:48:39.780 INFO ox: setting up npuvm
2702026-05-18T19:48:39.792ZMay 18 19:48:39.780 INFO cr1: installing frr
2712026-05-18T19:48:39.792ZMay 18 19:48:39.780 INFO waiting for ceos to initialize
2722026-05-18T19:48:39.792ZMay 18 19:48:39.780 DEBG [sc] ox: starting
2732026-05-18T19:48:39.792ZMay 18 19:48:39.780 DEBG [sc] ox: connecting to [::1]:61581
2742026-05-18T19:48:39.816ZMay 18 19:48:39.780 DEBG [sc] cr2: starting
2752026-05-18T19:48:39.816ZMay 18 19:48:39.781 DEBG [sc] cr2: connecting to [::1]:34930
2762026-05-18T19:48:39.816ZMay 18 19:48:39.781 DEBG [sc] cr1: starting
2772026-05-18T19:48:39.816ZMay 18 19:48:39.781 DEBG [sc] cr1: connecting to [::1]:32814
2782026-05-18T19:48:39.816ZMay 18 19:48:39.781 DEBG [sc] ox waiting for prompt
2792026-05-18T19:48:39.816ZMay 18 19:48:39.781 DEBG [sc] cr2 waiting for prompt
2802026-05-18T19:48:39.816ZMay 18 19:48:39.781 DEBG [sc] cr1 waiting for prompt
2812026-05-18T19:48:39.816ZMay 18 19:48:39.791 DEBG [sc] ox: logging in
2822026-05-18T19:48:39.816ZMay 18 19:48:39.792 DEBG [sc] cr1: logging in
2832026-05-18T19:48:39.816ZMay 18 19:48:39.792 DEBG [sc] cr2: logging in
2842026-05-18T19:48:39.880ZMay 18 19:48:39.868 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
2852026-05-18T19:48:39.936ZMay 18 19:48:39.925 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
2862026-05-18T19:48:40.171ZMay 18 19:48:40.160 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
2872026-05-18T19:48:42.211ZMay 18 19:48:42.199 INFO cr2: executing eos script show version
2882026-05-18T19:48:42.211ZMay 18 19:48:42.199 DEBG [sc] cr2: starting
2892026-05-18T19:48:42.211ZMay 18 19:48:42.199 DEBG [sc] cr2: connecting to [::1]:34930
2902026-05-18T19:48:42.235ZMay 18 19:48:42.200 DEBG [sc] cr2 waiting for prompt
2912026-05-18T19:48:42.235ZMay 18 19:48:42.211 DEBG [sc] cr2: logging in
2922026-05-18T19:48:42.366ZMay 18 19:48:42.354 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
2932026-05-18T19:48:46.197ZMay 18 19:48:46.185 DEBG [sc] ox: starting
2942026-05-18T19:48:46.197ZMay 18 19:48:46.185 DEBG [sc] ox: connecting to [::1]:61581
2952026-05-18T19:48:46.221ZMay 18 19:48:46.186 DEBG [sc] ox waiting for prompt
2962026-05-18T19:48:46.221ZMay 18 19:48:46.196 DEBG [sc] ox: logging in
2972026-05-18T19:48:46.286ZMay 18 19:48:46.275 DEBG [sc] ox: executing command `chmod +x npuvm`
2982026-05-18T19:48:46.352ZMay 18 19:48:46.341 DEBG [sc] ox: starting
2992026-05-18T19:48:46.352ZMay 18 19:48:46.341 DEBG [sc] ox: connecting to [::1]:61581
3002026-05-18T19:48:46.376ZMay 18 19:48:46.341 DEBG [sc] ox waiting for prompt
3012026-05-18T19:48:46.376ZMay 18 19:48:46.351 DEBG [sc] ox: logging in
3022026-05-18T19:48:46.452ZMay 18 19:48:46.441 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
3032026-05-18T19:48:50.346ZMay 18 19:48:50.335 DEBG [sc] cr2: starting
3042026-05-18T19:48:50.347ZMay 18 19:48:50.335 DEBG [sc] cr2: connecting to [::1]:34930
3052026-05-18T19:48:50.371ZMay 18 19:48:50.336 DEBG [sc] cr2 waiting for prompt
3062026-05-18T19:48:50.371ZMay 18 19:48:50.346 DEBG [sc] cr2: logging in
3072026-05-18T19:48:50.491ZMay 18 19:48:50.479 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3082026-05-18T19:48:52.622ZMay 18 19:48:52.611 INFO cr2: executing eos script show version
3092026-05-18T19:48:52.623ZMay 18 19:48:52.611 DEBG [sc] cr2: starting
3102026-05-18T19:48:52.623ZMay 18 19:48:52.611 DEBG [sc] cr2: connecting to [::1]:34930
3112026-05-18T19:48:52.647ZMay 18 19:48:52.612 DEBG [sc] cr2 waiting for prompt
3122026-05-18T19:48:52.647ZMay 18 19:48:52.622 DEBG [sc] cr2: logging in
3132026-05-18T19:48:52.798ZMay 18 19:48:52.787 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3142026-05-18T19:48:55.176ZMay 18 19:48:55.164 DEBG [sc] cr2: starting
3152026-05-18T19:48:55.176ZMay 18 19:48:55.164 DEBG [sc] cr2: connecting to [::1]:34930
3162026-05-18T19:48:55.201ZMay 18 19:48:55.164 DEBG [sc] cr2 waiting for prompt
3172026-05-18T19:48:55.201ZMay 18 19:48:55.175 DEBG [sc] cr2: logging in
3182026-05-18T19:48:55.353ZMay 18 19:48:55.341 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
3192026-05-18T19:48:57.526ZMay 18 19:48:57.514 INFO cr2: executing eos script show version
3202026-05-18T19:48:57.527ZMay 18 19:48:57.514 DEBG [sc] cr2: starting
3212026-05-18T19:48:57.527ZMay 18 19:48:57.514 DEBG [sc] cr2: connecting to [::1]:34930
3222026-05-18T19:48:57.551ZMay 18 19:48:57.514 DEBG [sc] cr2 waiting for prompt
3232026-05-18T19:48:57.551ZMay 18 19:48:57.524 DEBG [sc] cr2: logging in
3242026-05-18T19:48:57.690ZMay 18 19:48:57.678 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
3252026-05-18T19:49:00.221ZMay 18 19:49:00.209 INFO cr2: executing eos script
3262026-05-18T19:49:00.221Z enable
3272026-05-18T19:49:00.221Z configure
3282026-05-18T19:49:00.221Z ipv6 unicast-routing
3292026-05-18T19:49:00.221Z ip routing ipv6 interfaces
3302026-05-18T19:49:00.221Z ip routing
3312026-05-18T19:49:00.221Z ip route 1.2.3.0/24 null0
3322026-05-18T19:49:00.221Z ipv6 route fd99::/64 null0
3332026-05-18T19:49:00.221Z interface et1
3342026-05-18T19:49:00.221Z no switchport
3352026-05-18T19:49:00.221Z ipv6 enable
3362026-05-18T19:49:00.221Z
3372026-05-18T19:49:00.221Z router bgp 45
3382026-05-18T19:49:00.221Z router-id 1.2.3.1
3392026-05-18T19:49:00.221Z no bgp default ipv4-unicast
3402026-05-18T19:49:00.222Z timers bgp 2 6
3412026-05-18T19:49:00.222Z neighbor ebgp peer group
3422026-05-18T19:49:00.222Z neighbor ebgp remote-as 33
3432026-05-18T19:49:00.222Z neighbor interface Et1 peer-group ebgp
3442026-05-18T19:49:00.222Z address-family ipv4
3452026-05-18T19:49:00.222Z neighbor ebgp activate
3462026-05-18T19:49:00.222Z neighbor ebgp next-hop address-family ipv6 originate
3472026-05-18T19:49:00.222Z network 1.2.3.0/24
3482026-05-18T19:49:00.222Z exit
3492026-05-18T19:49:00.222Z address-family ipv6
3502026-05-18T19:49:00.222Z neighbor ebgp activate
3512026-05-18T19:49:00.222Z neighbor ebgp next-hop address-family ipv6 originate
3522026-05-18T19:49:00.222Z network fd99::/64
3532026-05-18T19:49:00.222Z exit
3542026-05-18T19:49:00.222Z exit
3552026-05-18T19:49:00.222Z
3562026-05-18T19:49:00.222ZMay 18 19:49:00.209 DEBG [sc] cr2: starting
3572026-05-18T19:49:00.222ZMay 18 19:49:00.209 DEBG [sc] cr2: connecting to [::1]:34930
3582026-05-18T19:49:00.247ZMay 18 19:49:00.210 DEBG [sc] cr2 waiting for prompt
3592026-05-18T19:49:00.247ZMay 18 19:49:00.220 DEBG [sc] cr2: logging in
3602026-05-18T19:49:00.363ZMay 18 19:49:00.352 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
3612026-05-18T19:49:00.363Z enable
3622026-05-18T19:49:00.363Z configure
3632026-05-18T19:49:00.363Z ipv6 unicast-routing
3642026-05-18T19:49:00.363Z ip routing ipv6 interfaces
3652026-05-18T19:49:00.363Z ip routing
3662026-05-18T19:49:00.363Z ip route 1.2.3.0/24 null0
3672026-05-18T19:49:00.363Z ipv6 route fd99::/64 null0
3682026-05-18T19:49:00.363Z interface et1
3692026-05-18T19:49:00.363Z no switchport
3702026-05-18T19:49:00.363Z ipv6 enable
3712026-05-18T19:49:00.363Z
3722026-05-18T19:49:00.364Z router bgp 45
3732026-05-18T19:49:00.364Z router-id 1.2.3.1
3742026-05-18T19:49:00.364Z no bgp default ipv4-unicast
3752026-05-18T19:49:00.364Z timers bgp 2 6
3762026-05-18T19:49:00.364Z neighbor ebgp peer group
3772026-05-18T19:49:00.364Z neighbor ebgp remote-as 33
3782026-05-18T19:49:00.364Z neighbor interface Et1 peer-group ebgp
3792026-05-18T19:49:00.364Z address-family ipv4
3802026-05-18T19:49:00.364Z neighbor ebgp activate
3812026-05-18T19:49:00.364Z neighbor ebgp next-hop address-family ipv6 originate
3822026-05-18T19:49:00.364Z network 1.2.3.0/24
3832026-05-18T19:49:00.364Z exit
3842026-05-18T19:49:00.364Z address-family ipv6
3852026-05-18T19:49:00.364Z neighbor ebgp activate
3862026-05-18T19:49:00.364Z neighbor ebgp next-hop address-family ipv6 originate
3872026-05-18T19:49:00.364Z network fd99::/64
3882026-05-18T19:49:00.364Z exit
3892026-05-18T19:49:00.364Z exit
3902026-05-18T19:49:00.364Z '`
3912026-05-18T19:49:18.069ZMay 18 19:49:18.058 INFO cr1: enabling frr daemon bgpd
3922026-05-18T19:49:18.069ZMay 18 19:49:18.058 DEBG [sc] cr1: starting
3932026-05-18T19:49:18.069ZMay 18 19:49:18.058 DEBG [sc] cr1: connecting to [::1]:32814
3942026-05-18T19:49:18.094ZMay 18 19:49:18.059 DEBG [sc] cr1 waiting for prompt
3952026-05-18T19:49:18.094ZMay 18 19:49:18.069 DEBG [sc] cr1: logging in
3962026-05-18T19:49:18.225ZMay 18 19:49:18.213 DEBG [sc] cr1: executing command `sed -i 's/bgpd=no/bgpd=yes/g' /etc/frr/daemons`
3972026-05-18T19:49:20.304ZMay 18 19:49:20.292 DEBG [sc] cr1: starting
3982026-05-18T19:49:20.304ZMay 18 19:49:20.292 DEBG [sc] cr1: connecting to [::1]:32814
3992026-05-18T19:49:20.328ZMay 18 19:49:20.293 DEBG [sc] cr1 waiting for prompt
4002026-05-18T19:49:20.328ZMay 18 19:49:20.302 DEBG [sc] cr1: logging in
4012026-05-18T19:49:20.469ZMay 18 19:49:20.457 DEBG [sc] cr1: executing command `systemctl restart frr`
4022026-05-18T19:49:28.097ZMay 18 19:49:28.085 INFO cr1: executing frr script
4032026-05-18T19:49:28.097Z configure
4042026-05-18T19:49:28.097Z ip forwarding
4052026-05-18T19:49:28.097Z ipv6 forwarding
4062026-05-18T19:49:28.097Z ip route 1.2.3.0/24 null0
4072026-05-18T19:49:28.097Z ipv6 route fd99::/64 null0
4082026-05-18T19:49:28.097Z router bgp 44
4092026-05-18T19:49:28.097Z no bgp ebgp-requires-policy
4102026-05-18T19:49:28.097Z timers bgp 2 6
4112026-05-18T19:49:28.097Z neighbor enp0s8 interface remote-as external
4122026-05-18T19:49:28.097Z neighbor enp0s8 timers connect 1
4132026-05-18T19:49:28.097Z address-family ipv4 unicast
4142026-05-18T19:49:28.098Z network 1.2.3.0/24
4152026-05-18T19:49:28.098Z neighbor enp0s8 activate
4162026-05-18T19:49:28.098Z exit-address-family
4172026-05-18T19:49:28.098Z address-family ipv6 unicast
4182026-05-18T19:49:28.098Z network fd99::/64
4192026-05-18T19:49:28.098Z neighbor enp0s8 activate
4202026-05-18T19:49:28.098Z exit-address-family
4212026-05-18T19:49:28.098Z exit
4222026-05-18T19:49:28.098Z
4232026-05-18T19:49:28.122ZMay 18 19:49:28.085 DEBG [sc] cr1: starting
4242026-05-18T19:49:28.122ZMay 18 19:49:28.085 DEBG [sc] cr1: connecting to [::1]:32814
4252026-05-18T19:49:28.122ZMay 18 19:49:28.086 DEBG [sc] cr1 waiting for prompt
4262026-05-18T19:49:28.122ZMay 18 19:49:28.096 DEBG [sc] cr1: logging in
4272026-05-18T19:49:28.240ZMay 18 19:49:28.229 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 ' '`
4282026-05-18T19:50:35.045ZMay 18 19:50:35.033 DEBG [sc] ox: starting
4292026-05-18T19:50:35.045ZMay 18 19:50:35.033 DEBG [sc] ox: connecting to [::1]:61581
4302026-05-18T19:50:35.069ZMay 18 19:50:35.033 DEBG [sc] ox waiting for prompt
4312026-05-18T19:50:35.069ZMay 18 19:50:35.044 DEBG [sc] ox: logging in
4322026-05-18T19:50:35.134ZMay 18 19:50:35.122 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
4332026-05-18T19:50:35.413ZMay 18 19:50:35.402 DEBG [sc] ox: starting
4342026-05-18T19:50:35.414ZMay 18 19:50:35.402 DEBG [sc] ox: connecting to [::1]:61581
4352026-05-18T19:50:35.438ZMay 18 19:50:35.403 DEBG [sc] ox waiting for prompt
4362026-05-18T19:50:35.438ZMay 18 19:50:35.413 DEBG [sc] ox: logging in
4372026-05-18T19:50:35.504ZMay 18 19:50:35.491 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4382026-05-18T19:50:36.526ZMay 18 19:50:36.515 DEBG [sc] ox: starting
4392026-05-18T19:50:36.526ZMay 18 19:50:36.515 DEBG [sc] ox: connecting to [::1]:61581
4402026-05-18T19:50:36.551ZMay 18 19:50:36.516 DEBG [sc] ox waiting for prompt
4412026-05-18T19:50:36.551ZMay 18 19:50:36.516 DEBG [sc] ox: logging in
4422026-05-18T19:50:36.605ZMay 18 19:50:36.594 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
4432026-05-18T19:50:36.663ZMay 18 19:50:36.649 DEBG [sc] ox: starting
4442026-05-18T19:50:36.663ZMay 18 19:50:36.649 DEBG [sc] ox: connecting to [::1]:61581
4452026-05-18T19:50:36.687ZMay 18 19:50:36.650 DEBG [sc] ox waiting for prompt
4462026-05-18T19:50:36.687ZMay 18 19:50:36.661 DEBG [sc] ox: logging in
4472026-05-18T19:50:36.749ZMay 18 19:50:36.737 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
4482026-05-18T19:50:36.804ZMay 18 19:50:36.793 DEBG [sc] ox: starting
4492026-05-18T19:50:36.804ZMay 18 19:50:36.793 DEBG [sc] ox: connecting to [::1]:61581
4502026-05-18T19:50:36.828ZMay 18 19:50:36.793 DEBG [sc] ox waiting for prompt
4512026-05-18T19:50:36.828ZMay 18 19:50:36.804 DEBG [sc] ox: logging in
4522026-05-18T19:50:36.893ZMay 18 19:50:36.881 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
4532026-05-18T19:50:36.948ZMay 18 19:50:36.936 DEBG [sc] ox: starting
4542026-05-18T19:50:36.948ZMay 18 19:50:36.936 DEBG [sc] ox: connecting to [::1]:61581
4552026-05-18T19:50:36.973ZMay 18 19:50:36.937 DEBG [sc] ox waiting for prompt
4562026-05-18T19:50:36.973ZMay 18 19:50:36.947 DEBG [sc] ox: logging in
4572026-05-18T19:50:37.036ZMay 18 19:50:37.024 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
4582026-05-18T19:50:37.092ZMay 18 19:50:37.080 DEBG [sc] ox: starting
4592026-05-18T19:50:37.092ZMay 18 19:50:37.080 DEBG [sc] ox: connecting to [::1]:61581
4602026-05-18T19:50:37.116ZMay 18 19:50:37.081 DEBG [sc] ox waiting for prompt
4612026-05-18T19:50:37.116ZMay 18 19:50:37.091 DEBG [sc] ox: logging in
4622026-05-18T19:50:37.180ZMay 18 19:50:37.168 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
4632026-05-18T19:50:37.234ZMay 18 19:50:37.223 DEBG [sc] ox: starting
4642026-05-18T19:50:37.234ZMay 18 19:50:37.223 DEBG [sc] ox: connecting to [::1]:61581
4652026-05-18T19:50:37.259ZMay 18 19:50:37.223 DEBG [sc] ox waiting for prompt
4662026-05-18T19:50:37.259ZMay 18 19:50:37.234 DEBG [sc] ox: logging in
4672026-05-18T19:50:37.322ZMay 18 19:50:37.311 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
4682026-05-18T19:50:37.378ZMay 18 19:50:37.366 DEBG [sc] ox: starting
4692026-05-18T19:50:37.378ZMay 18 19:50:37.366 DEBG [sc] ox: connecting to [::1]:61581
4702026-05-18T19:50:37.402ZMay 18 19:50:37.366 DEBG [sc] ox waiting for prompt
4712026-05-18T19:50:37.402ZMay 18 19:50:37.377 DEBG [sc] ox: logging in
4722026-05-18T19:50:37.466ZMay 18 19:50:37.455 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
4732026-05-18T19:50:37.522ZMay 18 19:50:37.510 DEBG [sc] ox: starting
4742026-05-18T19:50:37.522ZMay 18 19:50:37.510 DEBG [sc] ox: connecting to [::1]:61581
4752026-05-18T19:50:37.546ZMay 18 19:50:37.511 DEBG [sc] ox waiting for prompt
4762026-05-18T19:50:37.546ZMay 18 19:50:37.521 DEBG [sc] ox: logging in
4772026-05-18T19:50:37.610ZMay 18 19:50:37.598 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
4782026-05-18T19:50:37.682ZMay 18 19:50:37.670 INFO adding BGP router to mgd
4792026-05-18T19:50:40.703ZMay 18 19:50:40.692 INFO cr1: executing frr script show ip bgp json
4802026-05-18T19:50:40.729ZMay 18 19:50:40.692 DEBG [sc] cr1: starting
4812026-05-18T19:50:40.729ZMay 18 19:50:40.692 DEBG [sc] cr1: connecting to [::1]:32814
4822026-05-18T19:50:40.729ZMay 18 19:50:40.692 DEBG [sc] cr1 waiting for prompt
4832026-05-18T19:50:40.729ZMay 18 19:50:40.704 DEBG [sc] cr1: logging in
4842026-05-18T19:50:41.065ZMay 18 19:50:41.054 DEBG [sc] cr1: executing command `vtysh -c 'show ip bgp json'`
4852026-05-18T19:50:43.195ZMay 18 19:50:43.183 INFO cr1: executing frr script show bgp json
4862026-05-18T19:50:43.195ZMay 18 19:50:43.183 DEBG [sc] cr1: starting
4872026-05-18T19:50:43.195ZMay 18 19:50:43.183 DEBG [sc] cr1: connecting to [::1]:32814
4882026-05-18T19:50:43.219ZMay 18 19:50:43.184 DEBG [sc] cr1 waiting for prompt
4892026-05-18T19:50:43.219ZMay 18 19:50:43.194 DEBG [sc] cr1: logging in
4902026-05-18T19:50:43.338ZMay 18 19:50:43.326 DEBG [sc] cr1: executing command `vtysh -c 'show bgp json'`
4912026-05-18T19:50:45.457ZMay 18 19:50:45.446 INFO cr2: executing eos script show ip bgp | json
4922026-05-18T19:50:45.457ZMay 18 19:50:45.446 DEBG [sc] cr2: starting
4932026-05-18T19:50:45.457ZMay 18 19:50:45.446 DEBG [sc] cr2: connecting to [::1]:34930
4942026-05-18T19:50:45.481ZMay 18 19:50:45.446 DEBG [sc] cr2 waiting for prompt
4952026-05-18T19:50:45.481ZMay 18 19:50:45.457 DEBG [sc] cr2: logging in
4962026-05-18T19:50:45.814ZMay 18 19:50:45.803 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ip bgp | json'`
4972026-05-18T19:50:48.207ZMay 18 19:50:48.195 INFO cr2: executing eos script show ipv6 bgp | json
4982026-05-18T19:50:48.233ZMay 18 19:50:48.195 DEBG [sc] cr2: starting
4992026-05-18T19:50:48.233ZMay 18 19:50:48.196 DEBG [sc] cr2: connecting to [::1]:34930
5002026-05-18T19:50:48.233ZMay 18 19:50:48.196 DEBG [sc] cr2 waiting for prompt
5012026-05-18T19:50:48.233ZMay 18 19:50:48.206 DEBG [sc] cr2: logging in
5022026-05-18T19:50:48.350ZMay 18 19:50:48.339 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show ipv6 bgp | json'`
5032026-05-18T19:50:50.738ZMay 18 19:50:50.725 INFO trio bgp unnumbered test passed 🎉
5042026-05-18T19:50:50.738ZMay 18 19:50:50.725 INFO destroying runner for deployment mgtriou
5052026-05-18T19:50:50.738ZMay 18 19:50:50.725 INFO destroying deployment mgtriou
5062026-05-18T19:50:50.738ZMay 18 19:50:50.725 INFO destroying nodes
5072026-05-18T19:50:50.841ZMay 18 19:50:50.830 INFO destroying links
5082026-05-18T19:50:50.841ZMay 18 19:50:50.830 INFO destroying link mgtriou_ox_sn_vnic0
5092026-05-18T19:50:50.865ZMay 18 19:50:50.832 INFO destroying link mgtriou_ox_sn_sim0
5102026-05-18T19:50:50.865ZMay 18 19:50:50.834 INFO destroying link mgtriou_cr1_vn_vnic0
5112026-05-18T19:50:51.848ZMay 18 19:50:51.837 INFO destroying link mgtriou_cr1_vn_sim0
5122026-05-18T19:50:51.872ZMay 18 19:50:51.838 INFO destroying link mgtriou_ox_sn_vnic1
5132026-05-18T19:50:51.872ZMay 18 19:50:51.839 INFO destroying link mgtriou_ox_sn_sim1
5142026-05-18T19:50:51.872ZMay 18 19:50:51.840 INFO destroying link mgtriou_cr2_vn_vnic0
5152026-05-18T19:50:51.872ZMay 18 19:50:51.841 INFO destroying link mgtriou_cr2_vn_sim0
5162026-05-18T19:50:51.872ZMay 18 19:50:51.842 INFO destroying external links
5172026-05-18T19:50:51.872ZMay 18 19:50:51.842 INFO destroying external link mgtriou_ox_vn_vnic2
5182026-05-18T19:50:51.872ZMay 18 19:50:51.844 INFO destroying external link mgtriou_cr1_vn_vnic1
5192026-05-18T19:50:51.872ZMay 18 19:50:51.845 INFO destroying external link mgtriou_cr2_vn_vnic1
5202026-05-18T19:50:51.872ZMay 18 19:50:51.846 INFO destroying images
5212026-05-18T19:50:52.318ZMay 18 19:50:52.307 INFO destroying workspace at .falcon
5222026-05-18T19:50:52.345Z+ RUST_LOG=debug
5232026-05-18T19:50:52.345Z+ pfexec ./falcon-lab run trio-bfd-static-routing
5242026-05-18T19:50:52.369ZMay 18 19:50:52.351 DEBG using default route interface igb0
5252026-05-18T19:50:52.369ZMay 18 19:50:52.351 DEBG using default route interface igb0
5262026-05-18T19:50:52.369ZMay 18 19:50:52.351 DEBG using default route interface igb0
5272026-05-18T19:50:52.369ZMay 18 19:50:52.351 INFO launching runner: deployment(mgtriobfd) persistent(false) custom_propolis_binary(None) dataset(cpool/falcon) falcon_dir(.falcon)
5282026-05-18T19:50:52.369ZMay 18 19:50:52.351 INFO starting preflight for deployment mgtriobfd
5292026-05-18T19:50:53.101ZMay 18 19:50:53.089 INFO creating links
5302026-05-18T19:50:53.101ZMay 18 19:50:53.089 DEBG destroying link mgtriobfd_ox_sn_vnic0
5312026-05-18T19:50:53.101ZMay 18 19:50:53.089 DEBG destroying link mgtriobfd_ox_sn_sim0
5322026-05-18T19:50:53.101ZMay 18 19:50:53.090 INFO creating simnet link 'mgtriobfd_ox_sn_sim0'
5332026-05-18T19:50:53.125ZMay 18 19:50:53.092 INFO creating vnic link 'mgtriobfd_ox_sn_vnic0'
5342026-05-18T19:50:53.125ZMay 18 19:50:53.098 DEBG link pair created
5352026-05-18T19:50:53.125ZMay 18 19:50:53.098 DEBG destroying link mgtriobfd_cr1_vn_vnic0
5362026-05-18T19:50:53.125ZMay 18 19:50:53.098 DEBG destroying link mgtriobfd_cr1_vn_sim0
5372026-05-18T19:50:53.125ZMay 18 19:50:53.098 INFO creating simnet link 'mgtriobfd_cr1_vn_sim0'
5382026-05-18T19:50:53.125ZMay 18 19:50:53.100 INFO creating vnic link 'mgtriobfd_cr1_vn_vnic0'
5392026-05-18T19:50:53.125ZMay 18 19:50:53.105 DEBG link pair created
5402026-05-18T19:50:53.125ZMay 18 19:50:53.105 DEBG destroying link mgtriobfd_ox_sn_vnic1
5412026-05-18T19:50:53.125ZMay 18 19:50:53.105 DEBG destroying link mgtriobfd_ox_sn_sim1
5422026-05-18T19:50:53.125ZMay 18 19:50:53.105 INFO creating simnet link 'mgtriobfd_ox_sn_sim1'
5432026-05-18T19:50:53.125ZMay 18 19:50:53.106 INFO creating vnic link 'mgtriobfd_ox_sn_vnic1'
5442026-05-18T19:50:53.125ZMay 18 19:50:53.113 DEBG link pair created
5452026-05-18T19:50:53.125ZMay 18 19:50:53.113 DEBG destroying link mgtriobfd_cr2_vn_vnic0
5462026-05-18T19:50:53.125ZMay 18 19:50:53.113 DEBG destroying link mgtriobfd_cr2_vn_sim0
5472026-05-18T19:50:53.125ZMay 18 19:50:53.113 INFO creating simnet link 'mgtriobfd_cr2_vn_sim0'
5482026-05-18T19:50:53.149ZMay 18 19:50:53.114 INFO creating vnic link 'mgtriobfd_cr2_vn_vnic0'
5492026-05-18T19:50:53.149ZMay 18 19:50:53.120 DEBG link pair created
5502026-05-18T19:50:53.149ZMay 18 19:50:53.120 INFO creating external links
5512026-05-18T19:50:53.149ZMay 18 19:50:53.120 DEBG destroying external link mgtriobfd_ox_vn_vnic2
5522026-05-18T19:50:53.150ZMay 18 19:50:53.120 INFO creating external link mgtriobfd_ox_vn_vnic2
5532026-05-18T19:50:53.150ZMay 18 19:50:53.122 DEBG external link mgtriobfd_ox_vn_vnic2@igb0 created
5542026-05-18T19:50:53.150ZMay 18 19:50:53.122 DEBG destroying external link mgtriobfd_cr1_vn_vnic1
5552026-05-18T19:50:53.150ZMay 18 19:50:53.122 INFO creating external link mgtriobfd_cr1_vn_vnic1
5562026-05-18T19:50:53.150ZMay 18 19:50:53.123 DEBG external link mgtriobfd_cr1_vn_vnic1@igb0 created
5572026-05-18T19:50:53.150ZMay 18 19:50:53.123 DEBG destroying external link mgtriobfd_cr2_vn_vnic1
5582026-05-18T19:50:53.150ZMay 18 19:50:53.123 INFO creating external link mgtriobfd_cr2_vn_vnic1
5592026-05-18T19:50:53.150ZMay 18 19:50:53.124 DEBG external link mgtriobfd_cr2_vn_vnic1@igb0 created
5602026-05-18T19:50:53.150ZMay 18 19:50:53.124 INFO creating nodes
5612026-05-18T19:50:53.150ZMay 18 19:50:53.124 INFO ox: launching node
5622026-05-18T19:50:53.150ZMay 18 19:50:53.126 INFO cr1: launching node
5632026-05-18T19:50:53.150ZMay 18 19:50:53.128 INFO cr2: launching node
5642026-05-18T19:50:53.174ZMay 18 19:50:53.142 INFO launched instance ox with pid 894 on port 41121
5652026-05-18T19:50:53.174ZMay 18 19:50:53.142 INFO ox: instance ensure
5662026-05-18T19:50:53.174ZMay 18 19:50:53.142 INFO launched instance cr1 with pid 895 on port 39001
5672026-05-18T19:50:53.174ZMay 18 19:50:53.142 INFO cr1: instance ensure
5682026-05-18T19:50:53.174ZMay 18 19:50:53.142 INFO launched instance cr2 with pid 896 on port 49020
5692026-05-18T19:50:53.174ZMay 18 19:50:53.142 INFO cr2: instance ensure
5702026-05-18T19:50:55.321ZMay 18 19:50:55.309 INFO cr1: instance ensure completed after 0 retries
5712026-05-18T19:50:55.321ZMay 18 19:50:55.309 INFO cr1: instance run
5722026-05-18T19:50:55.345ZMay 18 19:50:55.309 DEBG [sc] cr1: starting
5732026-05-18T19:50:55.345ZMay 18 19:50:55.309 DEBG [sc] cr1: connecting to [::1]:39001
5742026-05-18T19:50:55.345ZMay 18 19:50:55.310 DEBG [sc] cr1 waiting for prompt
5752026-05-18T19:50:55.370ZMay 18 19:50:55.337 INFO ox: instance ensure completed after 0 retries
5762026-05-18T19:50:55.370ZMay 18 19:50:55.337 INFO ox: instance run
5772026-05-18T19:50:55.370ZMay 18 19:50:55.337 DEBG [sc] ox: starting
5782026-05-18T19:50:55.370ZMay 18 19:50:55.337 DEBG [sc] ox: connecting to [::1]:41121
5792026-05-18T19:50:55.370ZMay 18 19:50:55.338 DEBG [sc] ox waiting for prompt
5802026-05-18T19:50:55.393ZMay 18 19:50:55.379 INFO cr2: instance ensure completed after 0 retries
5812026-05-18T19:50:55.394ZMay 18 19:50:55.379 INFO cr2: instance run
5822026-05-18T19:50:55.394ZMay 18 19:50:55.379 DEBG [sc] cr2: starting
5832026-05-18T19:50:55.394ZMay 18 19:50:55.379 DEBG [sc] cr2: connecting to [::1]:49020
5842026-05-18T19:50:55.394ZMay 18 19:50:55.380 DEBG [sc] cr2 waiting for prompt
5852026-05-18T19:51:12.422ZMay 18 19:51:12.410 DEBG [sc] cr1: logging in
5862026-05-18T19:51:12.829ZMay 18 19:51:12.817 INFO cr1: mounting /opt/cargo-bay
5872026-05-18T19:51:12.829ZMay 18 19:51:12.817 DEBG [sc] cr1: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5882026-05-18T19:51:12.853ZMay 18 19:51:12.828 DEBG [sc] cr1: executing command `cd`
5892026-05-18T19:51:12.853ZMay 18 19:51:12.840 INFO cr1: finished mounting /opt/cargo-bay
5902026-05-18T19:51:12.853ZMay 18 19:51:12.840 DEBG [sc] cr1: executing command `hostname cr1`
5912026-05-18T19:51:12.902ZMay 18 19:51:12.851 DEBG [sc] cr1: executing command `echo 'cr1' > /etc/nodename`
5922026-05-18T19:51:12.902ZMay 18 19:51:12.862 DEBG [sc] cr1: executing command `echo '::1 cr1.local cr1' >> /etc/hosts`
5932026-05-18T19:51:12.926ZMay 18 19:51:12.873 DEBG [sc] cr1: executing command `echo '127.0.0.1 cr1.local cr1' >> /etc/hosts`
5942026-05-18T19:51:12.926ZMay 18 19:51:12.884 INFO cr1: logging out
5952026-05-18T19:51:14.964ZMay 18 19:51:14.952 INFO cr1: logged out
5962026-05-18T19:51:16.212ZMay 18 19:51:16.200 DEBG [sc] ox: logging in
5972026-05-18T19:51:16.388ZMay 18 19:51:16.376 INFO ox: mounting /opt/cargo-bay
5982026-05-18T19:51:16.388ZMay 18 19:51:16.376 DEBG [sc] ox: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
5992026-05-18T19:51:16.977ZMay 18 19:51:16.966 DEBG [sc] cr2: logging in
6002026-05-18T19:51:17.383ZMay 18 19:51:17.371 INFO cr2: mounting /opt/cargo-bay
6012026-05-18T19:51:17.383ZMay 18 19:51:17.371 DEBG [sc] cr2: executing command `mkdir -p /opt/cargo-bay; cd /opt/cargo-bay; p9kp pull`
6022026-05-18T19:51:17.407ZMay 18 19:51:17.393 DEBG [sc] cr2: executing command `cd`
6032026-05-18T19:51:17.430ZMay 18 19:51:17.404 INFO cr2: finished mounting /opt/cargo-bay
6042026-05-18T19:51:17.430ZMay 18 19:51:17.405 DEBG [sc] cr2: executing command `hostname cr2`
6052026-05-18T19:51:17.430ZMay 18 19:51:17.416 DEBG [sc] cr2: executing command `echo 'cr2' > /etc/nodename`
6062026-05-18T19:51:17.455ZMay 18 19:51:17.427 DEBG [sc] cr2: executing command `echo '::1 cr2.local cr2' >> /etc/hosts`
6072026-05-18T19:51:17.455ZMay 18 19:51:17.438 DEBG [sc] cr2: executing command `echo '127.0.0.1 cr2.local cr2' >> /etc/hosts`
6082026-05-18T19:51:17.478ZMay 18 19:51:17.449 INFO cr2: logging out
6092026-05-18T19:51:17.833ZMay 18 19:51:17.820 DEBG [sc] ox: executing command `cd`
6102026-05-18T19:51:17.857ZMay 18 19:51:17.831 INFO ox: finished mounting /opt/cargo-bay
6112026-05-18T19:51:17.857ZMay 18 19:51:17.831 DEBG [sc] ox: executing command `hostname ox`
6122026-05-18T19:51:17.857ZMay 18 19:51:17.842 DEBG [sc] ox: executing command `echo 'ox' > /etc/nodename`
6132026-05-18T19:51:17.881ZMay 18 19:51:17.853 DEBG [sc] ox: executing command `echo '::1 ox.local ox' >> /etc/hosts`
6142026-05-18T19:51:17.881ZMay 18 19:51:17.864 DEBG [sc] ox: executing command `echo '127.0.0.1 ox.local ox' >> /etc/hosts`
6152026-05-18T19:51:17.904ZMay 18 19:51:17.874 INFO ox: logging out
6162026-05-18T19:51:17.963ZMay 18 19:51:17.952 INFO ox: logged out
6172026-05-18T19:51:20.341ZMay 18 19:51:20.330 INFO cr2: logged out
6182026-05-18T19:51:20.365ZMay 18 19:51:20.330 DEBG [sc] ox: starting
6192026-05-18T19:51:20.365ZMay 18 19:51:20.330 DEBG [sc] ox: connecting to [::1]:41121
6202026-05-18T19:51:20.365ZMay 18 19:51:20.331 DEBG [sc] ox waiting for prompt
6212026-05-18T19:51:20.366ZMay 18 19:51:20.342 DEBG [sc] ox: logging in
6222026-05-18T19:51:20.442ZMay 18 19:51:20.430 DEBG [sc] ox: executing command `ipadm create-addr -T dhcp vioif1/dhcp`
6232026-05-18T19:51:26.759ZMay 18 19:51:26.747 DEBG [sc] ox: starting
6242026-05-18T19:51:26.759ZMay 18 19:51:26.747 DEBG [sc] ox: connecting to [::1]:41121
6252026-05-18T19:51:26.783ZMay 18 19:51:26.748 DEBG [sc] ox waiting for prompt
6262026-05-18T19:51:26.783ZMay 18 19:51:26.758 DEBG [sc] ox: logging in
6272026-05-18T19:51:26.848ZMay 18 19:51:26.837 DEBG [sc] ox: executing command `echo 'nameserver 1.1.1.1' > /etc/resolv.conf`
6282026-05-18T19:51:26.925ZMay 18 19:51:26.913 DEBG [sc] ox: starting
6292026-05-18T19:51:26.925ZMay 18 19:51:26.913 DEBG [sc] ox: connecting to [::1]:41121
6302026-05-18T19:51:26.949ZMay 18 19:51:26.914 DEBG [sc] ox waiting for prompt
6312026-05-18T19:51:26.949ZMay 18 19:51:26.924 DEBG [sc] ox: logging in
6322026-05-18T19:51:27.023ZMay 18 19:51:27.012 DEBG [sc] ox: executing command `ipadm show-addr vioif1/dhcp -p -o addr`
6332026-05-18T19:51:27.090ZMay 18 19:51:27.079 INFO cr1: installing frr
6342026-05-18T19:51:27.090ZMay 18 19:51:27.079 INFO waiting for ceos to initialize
6352026-05-18T19:51:27.091ZMay 18 19:51:27.079 INFO ox: setting up npuvm
6362026-05-18T19:51:27.115ZMay 18 19:51:27.079 DEBG [sc] cr2: starting
6372026-05-18T19:51:27.115ZMay 18 19:51:27.079 DEBG [sc] cr2: connecting to [::1]:49020
6382026-05-18T19:51:27.115ZMay 18 19:51:27.079 DEBG [sc] cr1: starting
6392026-05-18T19:51:27.115ZMay 18 19:51:27.079 DEBG [sc] cr1: connecting to [::1]:39001
6402026-05-18T19:51:27.115ZMay 18 19:51:27.079 DEBG [sc] ox: starting
6412026-05-18T19:51:27.115ZMay 18 19:51:27.079 DEBG [sc] ox: connecting to [::1]:41121
6422026-05-18T19:51:27.116ZMay 18 19:51:27.079 DEBG [sc] cr1 waiting for prompt
6432026-05-18T19:51:27.116ZMay 18 19:51:27.079 DEBG [sc] cr2 waiting for prompt
6442026-05-18T19:51:27.116ZMay 18 19:51:27.079 DEBG [sc] ox waiting for prompt
6452026-05-18T19:51:27.116ZMay 18 19:51:27.090 DEBG [sc] ox: logging in
6462026-05-18T19:51:27.116ZMay 18 19:51:27.091 DEBG [sc] cr2: logging in
6472026-05-18T19:51:27.116ZMay 18 19:51:27.091 DEBG [sc] cr1: logging in
6482026-05-18T19:51:27.189ZMay 18 19:51:27.178 DEBG [sc] ox: executing command `curl --retry 5 -OL https://buildomat.eng.oxide.computer/public/file/oxidecomputer//softnpu/image/fd2c726815cdb03c2687e1bf2912a9184905557b/npuvm`
6492026-05-18T19:51:27.246ZMay 18 19:51:27.235 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6502026-05-18T19:51:27.473ZMay 18 19:51:27.461 DEBG [sc] cr1: executing command `apt-get -y update && apt-get -y install frr`
6512026-05-18T19:51:29.489ZMay 18 19:51:29.477 INFO cr2: executing eos script show version
6522026-05-18T19:51:29.489ZMay 18 19:51:29.477 DEBG [sc] cr2: starting
6532026-05-18T19:51:29.489ZMay 18 19:51:29.477 DEBG [sc] cr2: connecting to [::1]:49020
6542026-05-18T19:51:29.514ZMay 18 19:51:29.478 DEBG [sc] cr2 waiting for prompt
6552026-05-18T19:51:29.514ZMay 18 19:51:29.488 DEBG [sc] cr2: logging in
6562026-05-18T19:51:29.654ZMay 18 19:51:29.642 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6572026-05-18T19:51:32.670ZMay 18 19:51:32.657 DEBG [sc] ox: starting
6582026-05-18T19:51:32.670ZMay 18 19:51:32.657 DEBG [sc] ox: connecting to [::1]:41121
6592026-05-18T19:51:32.694ZMay 18 19:51:32.657 DEBG [sc] ox waiting for prompt
6602026-05-18T19:51:32.694ZMay 18 19:51:32.668 DEBG [sc] ox: logging in
6612026-05-18T19:51:32.756ZMay 18 19:51:32.745 DEBG [sc] ox: executing command `chmod +x npuvm`
6622026-05-18T19:51:32.823ZMay 18 19:51:32.810 DEBG [sc] ox: starting
6632026-05-18T19:51:32.823ZMay 18 19:51:32.810 DEBG [sc] ox: connecting to [::1]:41121
6642026-05-18T19:51:32.847ZMay 18 19:51:32.811 DEBG [sc] ox waiting for prompt
6652026-05-18T19:51:32.847ZMay 18 19:51:32.822 DEBG [sc] ox: logging in
6662026-05-18T19:51:32.911ZMay 18 19:51:32.900 DEBG [sc] ox: executing command `./npuvm install --front-ports 2 --rear-ports 0 --pkt-source vioif0 `
6672026-05-18T19:51:36.605ZMay 18 19:51:36.593 INFO cr1: enabling frr daemon bfdd
6682026-05-18T19:51:36.605ZMay 18 19:51:36.593 DEBG [sc] cr1: starting
6692026-05-18T19:51:36.605ZMay 18 19:51:36.593 DEBG [sc] cr1: connecting to [::1]:39001
6702026-05-18T19:51:36.629ZMay 18 19:51:36.594 DEBG [sc] cr1 waiting for prompt
6712026-05-18T19:51:36.629ZMay 18 19:51:36.604 DEBG [sc] cr1: logging in
6722026-05-18T19:51:36.748ZMay 18 19:51:36.736 DEBG [sc] cr1: executing command `sed -i 's/bfdd=no/bfdd=yes/g' /etc/frr/daemons`
6732026-05-18T19:51:38.148ZMay 18 19:51:38.136 DEBG [sc] cr2: starting
6742026-05-18T19:51:38.148ZMay 18 19:51:38.136 DEBG [sc] cr2: connecting to [::1]:49020
6752026-05-18T19:51:38.172ZMay 18 19:51:38.137 DEBG [sc] cr2 waiting for prompt
6762026-05-18T19:51:38.172ZMay 18 19:51:38.147 DEBG [sc] cr2: logging in
6772026-05-18T19:51:38.302ZMay 18 19:51:38.290 DEBG [sc] cr2: executing command `docker inspect ceos --format '{{.State.Status}}'`
6782026-05-18T19:51:38.818ZMay 18 19:51:38.805 DEBG [sc] cr1: starting
6792026-05-18T19:51:38.818ZMay 18 19:51:38.805 DEBG [sc] cr1: connecting to [::1]:39001
6802026-05-18T19:51:38.842ZMay 18 19:51:38.806 DEBG [sc] cr1 waiting for prompt
6812026-05-18T19:51:38.842ZMay 18 19:51:38.816 DEBG [sc] cr1: logging in
6822026-05-18T19:51:38.961ZMay 18 19:51:38.948 DEBG [sc] cr1: executing command `systemctl restart frr`
6832026-05-18T19:51:40.438ZMay 18 19:51:40.425 INFO cr2: executing eos script show version
6842026-05-18T19:51:40.438ZMay 18 19:51:40.425 DEBG [sc] cr2: starting
6852026-05-18T19:51:40.438ZMay 18 19:51:40.425 DEBG [sc] cr2: connecting to [::1]:49020
6862026-05-18T19:51:40.463ZMay 18 19:51:40.426 DEBG [sc] cr2 waiting for prompt
6872026-05-18T19:51:40.463ZMay 18 19:51:40.436 DEBG [sc] cr2: logging in
6882026-05-18T19:51:40.614ZMay 18 19:51:40.602 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show version'`
6892026-05-18T19:51:42.981ZMay 18 19:51:42.970 INFO cr2: executing eos script
6902026-05-18T19:51:42.982Z enable
6912026-05-18T19:51:42.982Z configure
6922026-05-18T19:51:42.982Z ip routing
6932026-05-18T19:51:42.982Z ipv6 unicast-routing
6942026-05-18T19:51:42.982Z interface Ethernet1
6952026-05-18T19:51:42.982Z no switchport
6962026-05-18T19:51:42.982Z ip address 10.0.1.2/24
6972026-05-18T19:51:42.982Z ipv6 enable
6982026-05-18T19:51:42.982Z ipv6 address fd00:2::2/64
6992026-05-18T19:51:42.982Z bfd interval 300 min-rx 300 multiplier 3
7002026-05-18T19:51:42.982Z exit
7012026-05-18T19:51:42.982Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7022026-05-18T19:51:42.982Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7032026-05-18T19:51:42.982Z exit
7042026-05-18T19:51:42.982Z
7052026-05-18T19:51:42.982ZMay 18 19:51:42.970 DEBG [sc] cr2: starting
7062026-05-18T19:51:42.982ZMay 18 19:51:42.970 DEBG [sc] cr2: connecting to [::1]:49020
7072026-05-18T19:51:43.006ZMay 18 19:51:42.970 DEBG [sc] cr2 waiting for prompt
7082026-05-18T19:51:43.006ZMay 18 19:51:42.981 DEBG [sc] cr2: logging in
7092026-05-18T19:51:43.159ZMay 18 19:51:43.146 DEBG [sc] cr2: executing command `docker exec ceos Cli -c '
7102026-05-18T19:51:43.159Z enable
7112026-05-18T19:51:43.159Z configure
7122026-05-18T19:51:43.159Z ip routing
7132026-05-18T19:51:43.159Z ipv6 unicast-routing
7142026-05-18T19:51:43.159Z interface Ethernet1
7152026-05-18T19:51:43.159Z no switchport
7162026-05-18T19:51:43.159Z ip address 10.0.1.2/24
7172026-05-18T19:51:43.159Z ipv6 enable
7182026-05-18T19:51:43.159Z ipv6 address fd00:2::2/64
7192026-05-18T19:51:43.183Z bfd interval 300 min-rx 300 multiplier 3
7202026-05-18T19:51:43.183Z exit
7212026-05-18T19:51:43.183Z ip route 100.64.0.0/24 10.0.1.1 track bfd
7222026-05-18T19:51:43.183Z ipv6 route 3fff::/64 fd00:2::1 track bfd
7232026-05-18T19:51:43.183Z exit
7242026-05-18T19:51:43.183Z '`
7252026-05-18T19:51:46.571ZMay 18 19:51:46.559 INFO cr1: executing frr script
7262026-05-18T19:51:46.571Z configure
7272026-05-18T19:51:46.571Z interface enp0s8
7282026-05-18T19:51:46.571Z ip address 10.0.0.2/24
7292026-05-18T19:51:46.571Z ipv6 address fd00:1::2/64
7302026-05-18T19:51:46.571Z no shutdown
7312026-05-18T19:51:46.571Z exit
7322026-05-18T19:51:46.571Z bfd
7332026-05-18T19:51:46.571Z peer 10.0.0.1 local-address 10.0.0.2
7342026-05-18T19:51:46.571Z detect-multiplier 3
7352026-05-18T19:51:46.571Z receive-interval 300
7362026-05-18T19:51:46.571Z transmit-interval 300
7372026-05-18T19:51:46.571Z no shutdown
7382026-05-18T19:51:46.571Z exit
7392026-05-18T19:51:46.571Z peer fd00:1::1 local-address fd00:1::2
7402026-05-18T19:51:46.571Z detect-multiplier 3
7412026-05-18T19:51:46.571Z receive-interval 300
7422026-05-18T19:51:46.571Z transmit-interval 300
7432026-05-18T19:51:46.571Z no shutdown
7442026-05-18T19:51:46.571Z exit
7452026-05-18T19:51:46.571Z exit
7462026-05-18T19:51:46.571Z
7472026-05-18T19:51:46.571ZMay 18 19:51:46.559 DEBG [sc] cr1: starting
7482026-05-18T19:51:46.571ZMay 18 19:51:46.559 DEBG [sc] cr1: connecting to [::1]:39001
7492026-05-18T19:51:46.595ZMay 18 19:51:46.559 DEBG [sc] cr1 waiting for prompt
7502026-05-18T19:51:46.595ZMay 18 19:51:46.570 DEBG [sc] cr1: logging in
7512026-05-18T19:51:46.725ZMay 18 19:51:46.714 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 ' '`
7522026-05-18T19:53:21.828ZMay 18 19:53:21.815 DEBG [sc] ox: starting
7532026-05-18T19:53:21.828ZMay 18 19:53:21.815 DEBG [sc] ox: connecting to [::1]:41121
7542026-05-18T19:53:21.852ZMay 18 19:53:21.815 DEBG [sc] ox waiting for prompt
7552026-05-18T19:53:21.852ZMay 18 19:53:21.826 DEBG [sc] ox: logging in
7562026-05-18T19:53:21.915ZMay 18 19:53:21.902 DEBG [sc] ox: executing command `/root/scadm propolis load-program /root/libsidecar_lite.so`
7572026-05-18T19:53:22.254ZMay 18 19:53:22.240 DEBG [sc] ox: starting
7582026-05-18T19:53:22.254ZMay 18 19:53:22.240 DEBG [sc] ox: connecting to [::1]:41121
7592026-05-18T19:53:22.278ZMay 18 19:53:22.241 DEBG [sc] ox waiting for prompt
7602026-05-18T19:53:22.278ZMay 18 19:53:22.252 DEBG [sc] ox: logging in
7612026-05-18T19:53:22.343ZMay 18 19:53:22.329 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7622026-05-18T19:53:23.366ZMay 18 19:53:23.353 DEBG [sc] ox: starting
7632026-05-18T19:53:23.366ZMay 18 19:53:23.353 DEBG [sc] ox: connecting to [::1]:41121
7642026-05-18T19:53:23.390ZMay 18 19:53:23.354 DEBG [sc] ox waiting for prompt
7652026-05-18T19:53:23.390ZMay 18 19:53:23.354 DEBG [sc] ox: logging in
7662026-05-18T19:53:23.454ZMay 18 19:53:23.441 DEBG [sc] ox: executing command `dladm show-link tfportqsfp0_0 -p -o link`
7672026-05-18T19:53:23.521ZMay 18 19:53:23.508 DEBG [sc] ox: starting
7682026-05-18T19:53:23.521ZMay 18 19:53:23.508 DEBG [sc] ox: connecting to [::1]:41121
7692026-05-18T19:53:23.545ZMay 18 19:53:23.509 DEBG [sc] ox waiting for prompt
7702026-05-18T19:53:23.545ZMay 18 19:53:23.519 DEBG [sc] ox: logging in
7712026-05-18T19:53:23.622ZMay 18 19:53:23.609 DEBG [sc] ox: executing command `dladm show-link tfportqsfp1_0 -p -o link`
7722026-05-18T19:53:24.078ZMay 18 19:53:24.064 DEBG [sc] ox: starting
7732026-05-18T19:53:24.078ZMay 18 19:53:24.064 DEBG [sc] ox: connecting to [::1]:41121
7742026-05-18T19:53:24.102ZMay 18 19:53:24.065 DEBG [sc] ox waiting for prompt
7752026-05-18T19:53:24.102ZMay 18 19:53:24.075 DEBG [sc] ox: logging in
7762026-05-18T19:53:24.166ZMay 18 19:53:24.153 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp0_0/ll`
7772026-05-18T19:53:24.221ZMay 18 19:53:24.208 DEBG [sc] ox: starting
7782026-05-18T19:53:24.221ZMay 18 19:53:24.208 DEBG [sc] ox: connecting to [::1]:41121
7792026-05-18T19:53:24.245ZMay 18 19:53:24.208 DEBG [sc] ox waiting for prompt
7802026-05-18T19:53:24.245ZMay 18 19:53:24.219 DEBG [sc] ox: logging in
7812026-05-18T19:53:24.308ZMay 18 19:53:24.295 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/ll -p -o addr`
7822026-05-18T19:53:24.365ZMay 18 19:53:24.351 DEBG [sc] ox: starting
7832026-05-18T19:53:24.365ZMay 18 19:53:24.351 DEBG [sc] ox: connecting to [::1]:41121
7842026-05-18T19:53:24.389ZMay 18 19:53:24.352 DEBG [sc] ox waiting for prompt
7852026-05-18T19:53:24.389ZMay 18 19:53:24.361 DEBG [sc] ox: logging in
7862026-05-18T19:53:24.453ZMay 18 19:53:24.439 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.0.1/24 tfportqsfp0_0/v4`
7872026-05-18T19:53:25.091ZMay 18 19:53:25.078 DEBG [sc] ox: starting
7882026-05-18T19:53:25.091ZMay 18 19:53:25.078 DEBG [sc] ox: connecting to [::1]:41121
7892026-05-18T19:53:25.115ZMay 18 19:53:25.078 DEBG [sc] ox waiting for prompt
7902026-05-18T19:53:25.115ZMay 18 19:53:25.088 DEBG [sc] ox: logging in
7912026-05-18T19:53:25.179ZMay 18 19:53:25.166 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v4 -p -o addr`
7922026-05-18T19:53:25.235ZMay 18 19:53:25.221 DEBG [sc] ox: starting
7932026-05-18T19:53:25.235ZMay 18 19:53:25.221 DEBG [sc] ox: connecting to [::1]:41121
7942026-05-18T19:53:25.259ZMay 18 19:53:25.222 DEBG [sc] ox waiting for prompt
7952026-05-18T19:53:25.259ZMay 18 19:53:25.231 DEBG [sc] ox: logging in
7962026-05-18T19:53:25.322ZMay 18 19:53:25.309 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:1::1/64 tfportqsfp0_0/v6`
7972026-05-18T19:53:25.835ZMay 18 19:53:25.822 DEBG [sc] ox: starting
7982026-05-18T19:53:25.835ZMay 18 19:53:25.822 DEBG [sc] ox: connecting to [::1]:41121
7992026-05-18T19:53:25.859ZMay 18 19:53:25.823 DEBG [sc] ox waiting for prompt
8002026-05-18T19:53:25.860ZMay 18 19:53:25.832 DEBG [sc] ox: logging in
8012026-05-18T19:53:25.923ZMay 18 19:53:25.909 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp0_0/v6 -p -o addr`
8022026-05-18T19:53:25.979ZMay 18 19:53:25.965 DEBG [sc] ox: starting
8032026-05-18T19:53:25.979ZMay 18 19:53:25.965 DEBG [sc] ox: connecting to [::1]:41121
8042026-05-18T19:53:26.006ZMay 18 19:53:25.966 DEBG [sc] ox waiting for prompt
8052026-05-18T19:53:26.006ZMay 18 19:53:25.976 DEBG [sc] ox: logging in
8062026-05-18T19:53:26.066ZMay 18 19:53:26.053 DEBG [sc] ox: executing command `ipadm create-addr -T addrconf tfportqsfp1_0/ll`
8072026-05-18T19:53:26.121ZMay 18 19:53:26.107 DEBG [sc] ox: starting
8082026-05-18T19:53:26.121ZMay 18 19:53:26.107 DEBG [sc] ox: connecting to [::1]:41121
8092026-05-18T19:53:26.145ZMay 18 19:53:26.108 DEBG [sc] ox waiting for prompt
8102026-05-18T19:53:26.145ZMay 18 19:53:26.118 DEBG [sc] ox: logging in
8112026-05-18T19:53:26.208ZMay 18 19:53:26.195 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/ll -p -o addr`
8122026-05-18T19:53:26.264ZMay 18 19:53:26.251 DEBG [sc] ox: starting
8132026-05-18T19:53:26.264ZMay 18 19:53:26.251 DEBG [sc] ox: connecting to [::1]:41121
8142026-05-18T19:53:26.292ZMay 18 19:53:26.252 DEBG [sc] ox waiting for prompt
8152026-05-18T19:53:26.292ZMay 18 19:53:26.262 DEBG [sc] ox: logging in
8162026-05-18T19:53:26.352ZMay 18 19:53:26.338 DEBG [sc] ox: executing command `ipadm create-addr -T static -a 10.0.1.1/24 tfportqsfp1_0/v4`
8172026-05-18T19:53:26.856ZMay 18 19:53:26.843 DEBG [sc] ox: starting
8182026-05-18T19:53:26.856ZMay 18 19:53:26.843 DEBG [sc] ox: connecting to [::1]:41121
8192026-05-18T19:53:26.880ZMay 18 19:53:26.844 DEBG [sc] ox waiting for prompt
8202026-05-18T19:53:26.880ZMay 18 19:53:26.854 DEBG [sc] ox: logging in
8212026-05-18T19:53:26.946ZMay 18 19:53:26.932 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v4 -p -o addr`
8222026-05-18T19:53:27.003ZMay 18 19:53:26.987 DEBG [sc] ox: starting
8232026-05-18T19:53:27.003ZMay 18 19:53:26.987 DEBG [sc] ox: connecting to [::1]:41121
8242026-05-18T19:53:27.028ZMay 18 19:53:26.987 DEBG [sc] ox waiting for prompt
8252026-05-18T19:53:27.028ZMay 18 19:53:26.998 DEBG [sc] ox: logging in
8262026-05-18T19:53:27.088ZMay 18 19:53:27.074 DEBG [sc] ox: executing command `ipadm create-addr -T static -a fd00:2::1/64 tfportqsfp1_0/v6`
8272026-05-18T19:53:27.600ZMay 18 19:53:27.587 DEBG [sc] ox: starting
8282026-05-18T19:53:27.600ZMay 18 19:53:27.587 DEBG [sc] ox: connecting to [::1]:41121
8292026-05-18T19:53:27.630ZMay 18 19:53:27.588 DEBG [sc] ox waiting for prompt
8302026-05-18T19:53:27.630ZMay 18 19:53:27.597 DEBG [sc] ox: logging in
8312026-05-18T19:53:27.688ZMay 18 19:53:27.675 DEBG [sc] ox: executing command `ipadm show-addr tfportqsfp1_0/v6 -p -o addr`
8322026-05-18T19:53:27.744ZMay 18 19:53:27.731 DEBG [sc] ox: starting
8332026-05-18T19:53:27.744ZMay 18 19:53:27.731 DEBG [sc] ox: connecting to [::1]:41121
8342026-05-18T19:53:27.768ZMay 18 19:53:27.731 DEBG [sc] ox waiting for prompt
8352026-05-18T19:53:27.768ZMay 18 19:53:27.742 DEBG [sc] ox: logging in
8362026-05-18T19:53:27.836ZMay 18 19:53:27.819 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/mgd && /opt/cargo-bay/mgd run &> /tmp/mgd.log &`
8372026-05-18T19:53:27.910ZMay 18 19:53:27.873 DEBG [sc] ox: starting
8382026-05-18T19:53:27.910ZMay 18 19:53:27.874 DEBG [sc] ox: connecting to [::1]:41121
8392026-05-18T19:53:27.910ZMay 18 19:53:27.875 DEBG [sc] ox waiting for prompt
8402026-05-18T19:53:27.910ZMay 18 19:53:27.885 DEBG [sc] ox: logging in
8412026-05-18T19:53:27.975ZMay 18 19:53:27.961 DEBG [sc] ox: executing command `chmod +x /opt/cargo-bay/ddmd && /opt/cargo-bay/ddmd &> /tmp/ddm.log &`
8422026-05-18T19:53:28.047ZMay 18 19:53:28.033 INFO installing static v4 route 192.168.100.0/24
8432026-05-18T19:53:28.072ZMay 18 19:53:28.034 INFO installing static v6 route fd01::/64
8442026-05-18T19:53:28.072ZMay 18 19:53:28.035 INFO adding BFD peers for cr1 and cr2 (dual-stack)
8452026-05-18T19:53:28.072ZMay 18 19:53:28.037 INFO phase 1: both peers up
8462026-05-18T19:53:29.058ZMay 18 19:53:29.045 INFO cr1: executing frr script show bfd peers json
8472026-05-18T19:53:29.058ZMay 18 19:53:29.045 DEBG [sc] cr1: starting
8482026-05-18T19:53:29.082ZMay 18 19:53:29.045 DEBG [sc] cr1: connecting to [::1]:39001
8492026-05-18T19:53:29.082ZMay 18 19:53:29.045 DEBG [sc] cr1 waiting for prompt
8502026-05-18T19:53:29.082ZMay 18 19:53:29.056 DEBG [sc] cr1: logging in
8512026-05-18T19:53:29.447ZMay 18 19:53:29.434 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8522026-05-18T19:53:31.586ZMay 18 19:53:31.573 INFO cr1: executing frr script show bfd peers json
8532026-05-18T19:53:31.586ZMay 18 19:53:31.573 DEBG [sc] cr1: starting
8542026-05-18T19:53:31.586ZMay 18 19:53:31.573 DEBG [sc] cr1: connecting to [::1]:39001
8552026-05-18T19:53:31.611ZMay 18 19:53:31.573 DEBG [sc] cr1 waiting for prompt
8562026-05-18T19:53:31.611ZMay 18 19:53:31.584 DEBG [sc] cr1: logging in
8572026-05-18T19:53:31.720ZMay 18 19:53:31.707 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
8582026-05-18T19:53:33.852ZMay 18 19:53:33.838 INFO cr2: executing eos script show bfd peers | json
8592026-05-18T19:53:33.852ZMay 18 19:53:33.838 DEBG [sc] cr2: starting
8602026-05-18T19:53:33.852ZMay 18 19:53:33.838 DEBG [sc] cr2: connecting to [::1]:49020
8612026-05-18T19:53:33.876ZMay 18 19:53:33.839 DEBG [sc] cr2 waiting for prompt
8622026-05-18T19:53:33.876ZMay 18 19:53:33.850 DEBG [sc] cr2: logging in
8632026-05-18T19:53:34.217ZMay 18 19:53:34.204 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8642026-05-18T19:53:36.566ZMay 18 19:53:36.553 INFO cr2: executing eos script show bfd peers | json
8652026-05-18T19:53:36.566ZMay 18 19:53:36.553 DEBG [sc] cr2: starting
8662026-05-18T19:53:36.566ZMay 18 19:53:36.553 DEBG [sc] cr2: connecting to [::1]:49020
8672026-05-18T19:53:36.591ZMay 18 19:53:36.554 DEBG [sc] cr2 waiting for prompt
8682026-05-18T19:53:36.591ZMay 18 19:53:36.563 DEBG [sc] cr2: logging in
8692026-05-18T19:53:36.742ZMay 18 19:53:36.729 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8702026-05-18T19:53:39.087ZMay 18 19:53:39.074 INFO phase 2: pause bfdd on cr1
8712026-05-18T19:53:39.087ZMay 18 19:53:39.074 INFO cr1: pausing frr bfdd
8722026-05-18T19:53:39.087ZMay 18 19:53:39.074 DEBG [sc] cr1: starting
8732026-05-18T19:53:39.087ZMay 18 19:53:39.074 DEBG [sc] cr1: connecting to [::1]:39001
8742026-05-18T19:53:39.112ZMay 18 19:53:39.074 DEBG [sc] cr1 waiting for prompt
8752026-05-18T19:53:39.112ZMay 18 19:53:39.086 DEBG [sc] cr1: logging in
8762026-05-18T19:53:39.242ZMay 18 19:53:39.229 DEBG [sc] cr1: executing command `pkill -STOP bfdd`
8772026-05-18T19:53:41.346ZMay 18 19:53:41.332 INFO cr2: executing eos script show bfd peers | json
8782026-05-18T19:53:41.346ZMay 18 19:53:41.332 DEBG [sc] cr2: starting
8792026-05-18T19:53:41.346ZMay 18 19:53:41.332 DEBG [sc] cr2: connecting to [::1]:49020
8802026-05-18T19:53:41.370ZMay 18 19:53:41.333 DEBG [sc] cr2 waiting for prompt
8812026-05-18T19:53:41.370ZMay 18 19:53:41.343 DEBG [sc] cr2: logging in
8822026-05-18T19:53:41.478ZMay 18 19:53:41.465 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8832026-05-18T19:53:43.816ZMay 18 19:53:43.803 INFO cr2: executing eos script show bfd peers | json
8842026-05-18T19:53:43.816ZMay 18 19:53:43.803 DEBG [sc] cr2: starting
8852026-05-18T19:53:43.816ZMay 18 19:53:43.803 DEBG [sc] cr2: connecting to [::1]:49020
8862026-05-18T19:53:43.840ZMay 18 19:53:43.804 DEBG [sc] cr2 waiting for prompt
8872026-05-18T19:53:43.841ZMay 18 19:53:43.814 DEBG [sc] cr2: logging in
8882026-05-18T19:53:43.972ZMay 18 19:53:43.958 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
8892026-05-18T19:53:46.338ZMay 18 19:53:46.324 INFO phase 3: pause ceos on cr2
8902026-05-18T19:53:46.338ZMay 18 19:53:46.324 INFO cr2: pausing ceos
8912026-05-18T19:53:46.338ZMay 18 19:53:46.324 DEBG [sc] cr2: starting
8922026-05-18T19:53:46.338ZMay 18 19:53:46.324 DEBG [sc] cr2: connecting to [::1]:49020
8932026-05-18T19:53:46.362ZMay 18 19:53:46.325 DEBG [sc] cr2 waiting for prompt
8942026-05-18T19:53:46.362ZMay 18 19:53:46.334 DEBG [sc] cr2: logging in
8952026-05-18T19:53:46.480ZMay 18 19:53:46.467 DEBG [sc] cr2: executing command `docker pause ceos`
8962026-05-18T19:53:48.581ZMay 18 19:53:48.566 INFO phase 4: resume bfdd on cr1
8972026-05-18T19:53:48.581ZMay 18 19:53:48.566 INFO cr1: resuming frr bfdd
8982026-05-18T19:53:48.581ZMay 18 19:53:48.566 DEBG [sc] cr1: starting
8992026-05-18T19:53:48.581ZMay 18 19:53:48.566 DEBG [sc] cr1: connecting to [::1]:39001
9002026-05-18T19:53:48.606ZMay 18 19:53:48.567 DEBG [sc] cr1 waiting for prompt
9012026-05-18T19:53:48.606ZMay 18 19:53:48.578 DEBG [sc] cr1: logging in
9022026-05-18T19:53:48.735ZMay 18 19:53:48.722 DEBG [sc] cr1: executing command `pkill -CONT bfdd`
9032026-05-18T19:53:50.815ZMay 18 19:53:50.802 INFO cr1: executing frr script show bfd peers json
9042026-05-18T19:53:50.815ZMay 18 19:53:50.802 DEBG [sc] cr1: starting
9052026-05-18T19:53:50.815ZMay 18 19:53:50.802 DEBG [sc] cr1: connecting to [::1]:39001
9062026-05-18T19:53:50.839ZMay 18 19:53:50.803 DEBG [sc] cr1 waiting for prompt
9072026-05-18T19:53:50.839ZMay 18 19:53:50.811 DEBG [sc] cr1: logging in
9082026-05-18T19:53:50.957ZMay 18 19:53:50.944 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9092026-05-18T19:53:53.104ZMay 18 19:53:53.091 INFO cr1: executing frr script show bfd peers json
9102026-05-18T19:53:53.128ZMay 18 19:53:53.091 DEBG [sc] cr1: starting
9112026-05-18T19:53:53.128ZMay 18 19:53:53.091 DEBG [sc] cr1: connecting to [::1]:39001
9122026-05-18T19:53:53.128ZMay 18 19:53:53.091 DEBG [sc] cr1 waiting for prompt
9132026-05-18T19:53:53.128ZMay 18 19:53:53.101 DEBG [sc] cr1: logging in
9142026-05-18T19:53:53.258ZMay 18 19:53:53.245 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9152026-05-18T19:53:55.418ZMay 18 19:53:55.405 INFO phase 5: unpause ceos on cr2
9162026-05-18T19:53:55.418ZMay 18 19:53:55.405 INFO cr2: unpausing ceos
9172026-05-18T19:53:55.418ZMay 18 19:53:55.405 DEBG [sc] cr2: starting
9182026-05-18T19:53:55.418ZMay 18 19:53:55.405 DEBG [sc] cr2: connecting to [::1]:49020
9192026-05-18T19:53:55.443ZMay 18 19:53:55.406 DEBG [sc] cr2 waiting for prompt
9202026-05-18T19:53:55.443ZMay 18 19:53:55.417 DEBG [sc] cr2: logging in
9212026-05-18T19:53:55.562ZMay 18 19:53:55.549 DEBG [sc] cr2: executing command `docker unpause ceos`
9222026-05-18T19:53:57.662ZMay 18 19:53:57.649 INFO cr1: executing frr script show bfd peers json
9232026-05-18T19:53:57.662ZMay 18 19:53:57.649 DEBG [sc] cr1: starting
9242026-05-18T19:53:57.662ZMay 18 19:53:57.649 DEBG [sc] cr1: connecting to [::1]:39001
9252026-05-18T19:53:57.686ZMay 18 19:53:57.649 DEBG [sc] cr1 waiting for prompt
9262026-05-18T19:53:57.686ZMay 18 19:53:57.661 DEBG [sc] cr1: logging in
9272026-05-18T19:53:57.828ZMay 18 19:53:57.815 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9282026-05-18T19:53:59.976ZMay 18 19:53:59.963 INFO cr1: executing frr script show bfd peers json
9292026-05-18T19:53:59.976ZMay 18 19:53:59.963 DEBG [sc] cr1: starting
9302026-05-18T19:53:59.976ZMay 18 19:53:59.963 DEBG [sc] cr1: connecting to [::1]:39001
9312026-05-18T19:54:00.001ZMay 18 19:53:59.964 DEBG [sc] cr1 waiting for prompt
9322026-05-18T19:54:00.001ZMay 18 19:53:59.974 DEBG [sc] cr1: logging in
9332026-05-18T19:54:00.130ZMay 18 19:54:00.117 DEBG [sc] cr1: executing command `vtysh -c 'show bfd peers json'`
9342026-05-18T19:54:02.263ZMay 18 19:54:02.250 INFO cr2: executing eos script show bfd peers | json
9352026-05-18T19:54:02.287ZMay 18 19:54:02.250 DEBG [sc] cr2: starting
9362026-05-18T19:54:02.287ZMay 18 19:54:02.250 DEBG [sc] cr2: connecting to [::1]:49020
9372026-05-18T19:54:02.287ZMay 18 19:54:02.251 DEBG [sc] cr2 waiting for prompt
9382026-05-18T19:54:02.288ZMay 18 19:54:02.262 DEBG [sc] cr2: logging in
9392026-05-18T19:54:02.410ZMay 18 19:54:02.396 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9402026-05-18T19:54:04.733ZMay 18 19:54:04.719 INFO cr2: executing eos script show bfd peers | json
9412026-05-18T19:54:04.733ZMay 18 19:54:04.719 DEBG [sc] cr2: starting
9422026-05-18T19:54:04.733ZMay 18 19:54:04.719 DEBG [sc] cr2: connecting to [::1]:49020
9432026-05-18T19:54:04.758ZMay 18 19:54:04.720 DEBG [sc] cr2 waiting for prompt
9442026-05-18T19:54:04.758ZMay 18 19:54:04.731 DEBG [sc] cr2: logging in
9452026-05-18T19:54:04.886ZMay 18 19:54:04.873 DEBG [sc] cr2: executing command `docker exec ceos Cli -c 'show bfd peers | json'`
9462026-05-18T19:54:07.258ZMay 18 19:54:07.244 INFO trio bfd static routing test passed 🎉
9472026-05-18T19:54:07.258ZMay 18 19:54:07.245 INFO destroying runner for deployment mgtriobfd
9482026-05-18T19:54:07.258ZMay 18 19:54:07.245 INFO destroying deployment mgtriobfd
9492026-05-18T19:54:07.258ZMay 18 19:54:07.245 INFO destroying nodes
9502026-05-18T19:54:07.378ZMay 18 19:54:07.365 INFO destroying links
9512026-05-18T19:54:07.378ZMay 18 19:54:07.365 INFO destroying link mgtriobfd_ox_sn_vnic0
9522026-05-18T19:54:07.403ZMay 18 19:54:07.366 INFO destroying link mgtriobfd_ox_sn_sim0
9532026-05-18T19:54:07.403ZMay 18 19:54:07.367 INFO destroying link mgtriobfd_cr1_vn_vnic0
9542026-05-18T19:54:08.383ZMay 18 19:54:08.370 INFO destroying link mgtriobfd_cr1_vn_sim0
9552026-05-18T19:54:08.408ZMay 18 19:54:08.371 INFO destroying link mgtriobfd_ox_sn_vnic1
9562026-05-18T19:54:08.408ZMay 18 19:54:08.372 INFO destroying link mgtriobfd_ox_sn_sim1
9572026-05-18T19:54:08.408ZMay 18 19:54:08.373 INFO destroying link mgtriobfd_cr2_vn_vnic0
9582026-05-18T19:54:08.408ZMay 18 19:54:08.374 INFO destroying link mgtriobfd_cr2_vn_sim0
9592026-05-18T19:54:08.408ZMay 18 19:54:08.375 INFO destroying external links
9602026-05-18T19:54:08.408ZMay 18 19:54:08.375 INFO destroying external link mgtriobfd_ox_vn_vnic2
9612026-05-18T19:54:08.408ZMay 18 19:54:08.376 INFO destroying external link mgtriobfd_cr1_vn_vnic1
9622026-05-18T19:54:08.408ZMay 18 19:54:08.377 INFO destroying external link mgtriobfd_cr2_vn_vnic1
9632026-05-18T19:54:08.408ZMay 18 19:54:08.379 INFO destroying images
9642026-05-18T19:54:08.887ZMay 18 19:54:08.873 INFO destroying workspace at .falcon
9652026-05-18T19:54:08.911Zprocess exited: duration 698168 ms, exit code 0
 
9662026-05-18T19:54:08.961Zfound 0 output files