2026-05-16 00:23:53.170120 : Get input param file /home/super/workspace/PhoenixWingDailySRv6Test/jenkins_850/input_param_json.txt
2026-05-16 00:23:53.170517 : Get file lock for {'user_info': 'PhoenixWingDailySRv6Test_850', 'testbed_location': 'NO_PREFERENCE'}
2026-05-16 00:23:54.171658 : Before: testbed_location NO_PREFERENCE, uinfo PhoenixWingDailySRv6Test_850, action read, index -1, current index 0
2026-05-16 00:23:54.171667 : After: testbed_location NO_PREFERENCE, uinfo PhoenixWingDailySRv6Test_850, action read, index -1, current index 0
2026-05-16 00:23:54.171671 : Found index 0 for action read, user_info PhoenixWingDailySRv6Test_850
2026-05-16 00:23:54.171690 : Release file lock for {'user_info': 'PhoenixWingDailySRv6Test_850', 'testbed_location': 'NO_PREFERENCE', 'action': 'read', 'output_vm': {'index': 2, 'user_info': 'PhoenixWingDailySRv6Test_850', 'time': 'Sat May 16 00:08:03 2026'}, 'output_index': 0, 'output_prefix': '192.168.0'}
2026-05-16 00:23:54.171738 : read_vm_reservation : {"user_info": "PhoenixWingDailySRv6Test_850", "testbed_location": "NO_PREFERENCE", "action": "read", "output_vm": {"index": 2, "user_info": "PhoenixWingDailySRv6Test_850", "time": "Sat May 16 00:08:03 2026"}, "output_index": 0, "output_prefix": "192.168.0"}
2026-05-16 00:23:54.171913 : ifconfig | grep 30.57.186.111
2026-05-16 00:23:54.174979 : DEBUG_ARR:         inet 30.57.186.111  netmask 255.255.255.0  broadcast 30.57.186.255
2026-05-16 00:23:54.175027 : Found local server setting forr 30.57.186.111
2026-05-16 00:23:54.175050 : Set local ip as 192.168.0.2
{   'address': '30.57.186.111',
    'host_port': 'br0',
    'jenkin_node_name': 'Pytest_node3',
    'password': 'ais12#$',
    'user': 'super',
    'vm_bridge': 'vmbr0',
    'vm_gw': '192.168.0.1',
    'vmip': '192.168.0.2'}
2026-05-16 00:23:54.175252 : mkdir -p /tmp/local_cache//1778916233.1701105/
Run pytest on 30.57.186.111 vmip 192.168.0.2, vm name pytest_vm_192.168.0.2
2026-05-16 00:23:54.177809 : Start bringing up test VMs
2026-05-16 00:23:54.177849 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "cd ~/sonic-mgmt/ansible; sudo ./setup-management-network.sh"
2026-05-16 00:24:10.819056 : DEBUG_ARR: Refreshing apt package lists...
2026-05-16 00:24:10.819099 : DEBUG_ARR: Get:1 http://security.ubuntu.com/ubuntu focal-security InRelease [128 kB]
2026-05-16 00:24:10.819104 : DEBUG_ARR: Hit:2 http://archive.ubuntu.com/ubuntu focal InRelease
2026-05-16 00:24:10.819107 : DEBUG_ARR: Get:3 http://archive.ubuntu.com/ubuntu focal-updates InRelease [128 kB]
2026-05-16 00:24:10.819115 : DEBUG_ARR: Get:4 http://security.ubuntu.com/ubuntu focal-security/main amd64 Packages [3610 kB]
2026-05-16 00:24:10.819118 : DEBUG_ARR: Get:5 http://security.ubuntu.com/ubuntu focal-security/main Translation-en [518 kB]
2026-05-16 00:24:10.819124 : DEBUG_ARR: Get:6 http://security.ubuntu.com/ubuntu focal-security/main amd64 c-n-f Metadata [14.4 kB]
2026-05-16 00:24:10.819128 : DEBUG_ARR: Get:7 http://security.ubuntu.com/ubuntu focal-security/restricted amd64 Packages [3828 kB]
2026-05-16 00:24:10.819131 : DEBUG_ARR: Get:8 http://security.ubuntu.com/ubuntu focal-security/restricted Translation-en [527 kB]
2026-05-16 00:24:10.819134 : DEBUG_ARR: Get:9 http://security.ubuntu.com/ubuntu focal-security/restricted amd64 c-n-f Metadata [584 B]
2026-05-16 00:24:10.819137 : DEBUG_ARR: Get:10 http://security.ubuntu.com/ubuntu focal-security/universe amd64 Packages [1052 kB]
2026-05-16 00:24:10.819140 : DEBUG_ARR: Get:11 http://security.ubuntu.com/ubuntu focal-security/universe Translation-en [220 kB]
2026-05-16 00:24:10.819142 : DEBUG_ARR: Get:12 http://security.ubuntu.com/ubuntu focal-security/universe amd64 c-n-f Metadata [22.4 kB]
2026-05-16 00:24:10.819145 : DEBUG_ARR: Get:13 http://security.ubuntu.com/ubuntu focal-security/multiverse amd64 Packages [26.7 kB]
2026-05-16 00:24:10.819148 : DEBUG_ARR: Get:14 http://security.ubuntu.com/ubuntu focal-security/multiverse Translation-en [6416 B]
2026-05-16 00:24:10.819151 : DEBUG_ARR: Get:15 http://security.ubuntu.com/ubuntu focal-security/multiverse amd64 c-n-f Metadata [604 B]
2026-05-16 00:24:10.819154 : DEBUG_ARR: Get:16 http://archive.ubuntu.com/ubuntu focal-backports InRelease [128 kB]
2026-05-16 00:24:10.819157 : DEBUG_ARR: Get:17 http://archive.ubuntu.com/ubuntu focal-updates/main amd64 Packages [4004 kB]
2026-05-16 00:24:10.819160 : DEBUG_ARR: Get:18 http://archive.ubuntu.com/ubuntu focal-updates/main Translation-en [601 kB]
2026-05-16 00:24:10.819163 : DEBUG_ARR: Get:19 http://archive.ubuntu.com/ubuntu focal-updates/main amd64 c-n-f Metadata [18.0 kB]
2026-05-16 00:24:10.819166 : DEBUG_ARR: Get:20 http://archive.ubuntu.com/ubuntu focal-updates/restricted amd64 Packages [3983 kB]
2026-05-16 00:24:10.819169 : DEBUG_ARR: Get:21 http://archive.ubuntu.com/ubuntu focal-updates/restricted Translation-en [548 kB]
2026-05-16 00:24:10.819172 : DEBUG_ARR: Get:22 http://archive.ubuntu.com/ubuntu focal-updates/restricted amd64 c-n-f Metadata [604 B]
2026-05-16 00:24:10.819175 : DEBUG_ARR: Get:23 http://archive.ubuntu.com/ubuntu focal-updates/universe amd64 Packages [1275 kB]
2026-05-16 00:24:10.819178 : DEBUG_ARR: Get:24 http://archive.ubuntu.com/ubuntu focal-updates/universe Translation-en [302 kB]
2026-05-16 00:24:10.819181 : DEBUG_ARR: Get:25 http://archive.ubuntu.com/ubuntu focal-updates/universe amd64 c-n-f Metadata [29.3 kB]
2026-05-16 00:24:10.819184 : DEBUG_ARR: Get:26 http://archive.ubuntu.com/ubuntu focal-updates/multiverse amd64 Packages [29.8 kB]
2026-05-16 00:24:10.819187 : DEBUG_ARR: Get:27 http://archive.ubuntu.com/ubuntu focal-updates/multiverse Translation-en [8284 B]
2026-05-16 00:24:10.819190 : DEBUG_ARR: Get:28 http://archive.ubuntu.com/ubuntu focal-updates/multiverse amd64 c-n-f Metadata [688 B]
2026-05-16 00:24:10.819193 : DEBUG_ARR: Get:29 http://archive.ubuntu.com/ubuntu focal-backports/main amd64 Packages [46.1 kB]
2026-05-16 00:24:10.819196 : DEBUG_ARR: Get:30 http://archive.ubuntu.com/ubuntu focal-backports/main Translation-en [16.2 kB]
2026-05-16 00:24:10.819199 : DEBUG_ARR: Get:31 http://archive.ubuntu.com/ubuntu focal-backports/universe amd64 Packages [25.0 kB]
2026-05-16 00:24:10.819202 : DEBUG_ARR: Get:32 http://archive.ubuntu.com/ubuntu focal-backports/universe Translation-en [16.3 kB]
2026-05-16 00:24:10.819208 : DEBUG_ARR: Fetched 21.1 MB in 5s (4642 kB/s)
2026-05-16 00:24:10.819212 : DEBUG_ARR: Reading package lists...
2026-05-16 00:24:10.819215 : DEBUG_ARR: 
2026-05-16 00:24:10.819218 : DEBUG_ARR: STEP 1: Checking for j2cli package...
2026-05-16 00:24:10.819221 : DEBUG_ARR: /usr/local/bin/j2
2026-05-16 00:24:10.819224 : DEBUG_ARR: 
2026-05-16 00:24:10.819227 : DEBUG_ARR: STEP 2: Checking for bridge-utils package...
2026-05-16 00:24:10.819230 : DEBUG_ARR: /usr/sbin/brctl
2026-05-16 00:24:10.819233 : DEBUG_ARR: 
2026-05-16 00:24:10.819236 : DEBUG_ARR: STEP 3: Checking for net-tools package...
2026-05-16 00:24:10.819239 : DEBUG_ARR: /usr/sbin/ifconfig
2026-05-16 00:24:10.819242 : DEBUG_ARR: 
2026-05-16 00:24:10.819245 : DEBUG_ARR: STEP 4: Checking for ethtool package...
2026-05-16 00:24:10.819248 : DEBUG_ARR: /usr/sbin/ethtool
2026-05-16 00:24:10.819251 : DEBUG_ARR: 
2026-05-16 00:24:10.819257 : DEBUG_ARR: STEP 5: Delete existed br1...
2026-05-16 00:24:10.819260 : DEBUG_ARR: Not delete existed bridge or br1 not exists, skipping...
2026-05-16 00:24:10.819263 : DEBUG_ARR: 
2026-05-16 00:24:10.819266 : DEBUG_ARR: STEP 6: Checking if bridge br1 already exists...
2026-05-16 00:24:10.819269 : DEBUG_ARR: br1: error fetching interface information: Device not found
2026-05-16 00:24:10.819272 : DEBUG_ARR: br1 not found, creating bridge network
2026-05-16 00:24:10.819275 : DEBUG_ARR: bridge name	bridge id		STP enabled	interfaces
2026-05-16 00:24:10.819278 : DEBUG_ARR: br1		8000.000000000000	no		
2026-05-16 00:24:10.819281 : DEBUG_ARR: 
2026-05-16 00:24:10.819284 : DEBUG_ARR: STEP 7: Configuring br1 interface...
2026-05-16 00:24:10.819287 : DEBUG_ARR: Assigning 10.250.0.1/24 to br1
2026-05-16 00:24:10.819290 : DEBUG_ARR: Bringing up br1
2026-05-16 00:24:10.819293 : DEBUG_ARR: 
2026-05-16 00:24:10.819296 : DEBUG_ARR: COMPLETE. Bridge info:
2026-05-16 00:24:10.819375 : DEBUG_ARR: 
2026-05-16 00:24:10.819380 : DEBUG_ARR: bridge name	bridge id		STP enabled	interfaces
2026-05-16 00:24:10.819383 : DEBUG_ARR: br1		8000.000000000000	no		
2026-05-16 00:24:10.819386 : DEBUG_ARR: 
2026-05-16 00:24:10.819389 : DEBUG_ARR: br1: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
2026-05-16 00:24:10.819392 : DEBUG_ARR:         inet 10.250.0.1  netmask 255.255.255.0  broadcast 10.250.0.255
2026-05-16 00:24:10.819395 : DEBUG_ARR:         inet6 fec0::1  prefixlen 64  scopeid 0x40<site>
2026-05-16 00:24:10.819398 : DEBUG_ARR:         inet6 fe80::58cf:59ff:fe5d:90dc  prefixlen 64  scopeid 0x20<link>
2026-05-16 00:24:10.819401 : DEBUG_ARR:         ether 5a:cf:59:5d:90:dc  txqueuelen 1000  (Ethernet)
2026-05-16 00:24:10.819405 : DEBUG_ARR:         RX packets 0  bytes 0 (0.0 B)
2026-05-16 00:24:10.819408 : DEBUG_ARR:         RX errors 0  dropped 0  overruns 0  frame 0
2026-05-16 00:24:10.819411 : DEBUG_ARR:         TX packets 0  bytes 0 (0.0 B)
2026-05-16 00:24:10.819414 : DEBUG_ARR:         TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
2026-05-16 00:24:10.819420 : DEBUG_ARR: 
2026-05-16 00:24:10.819454 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "docker system prune --force"
2026-05-16 00:24:14.300216 : DEBUG_ARR: Deleted Containers:
2026-05-16 00:24:14.300256 : DEBUG_ARR: 477d0e6e44a4425b0bec9d20c55ff11e9a1120037f08bcafba4f0cb158da4f14
2026-05-16 00:24:14.300261 : DEBUG_ARR: 
2026-05-16 00:24:14.300268 : DEBUG_ARR: Deleted Images:
2026-05-16 00:24:14.300271 : DEBUG_ARR: deleted: sha256:d0e75110437359207d09aee6d06c911ed810fdbe902b35e89ba81cc2afbb99c0
2026-05-16 00:24:14.300275 : DEBUG_ARR: deleted: sha256:392a5abe4ef46dcc470d372a7d5bef90bbcc4020675aebce009497644b56211b
2026-05-16 00:24:14.300278 : DEBUG_ARR: deleted: sha256:68fea0acce8ce064fbc73abb7eb608b8f8d9ce67b4d4b864c4bf5fd93414a200
2026-05-16 00:24:14.300281 : DEBUG_ARR: deleted: sha256:b1840c48e4f86f4927eaafad792d3f7fe2bb48e0c49eca20e82db361a672bdd6
2026-05-16 00:24:14.300284 : DEBUG_ARR: deleted: sha256:597a83131ddad3c576ce8c87ab7641c2866673c5a3f0f6a4709238e4c7eaab02
2026-05-16 00:24:14.300287 : DEBUG_ARR: deleted: sha256:3427583a4cbc30c2af8d048c85bd01b3d292425bf6387dba12038264301faff8
2026-05-16 00:24:14.300290 : DEBUG_ARR: deleted: sha256:027c9a6fc18b21172a9e82984949144f8d13c2776fffde42c75fea0384803afb
2026-05-16 00:24:14.300293 : DEBUG_ARR: deleted: sha256:e17aa51c03089b366c4af99f41e8f64c1f776797be1b8444f8d7efc06f8a8b99
2026-05-16 00:24:14.300296 : DEBUG_ARR: deleted: sha256:05ee2769ae30b3193aa20a1385642030596c5603f17f7d889eacdf30fd57492d
2026-05-16 00:24:14.300299 : DEBUG_ARR: deleted: sha256:110e95e02f774c7b02f2de60eb6fa5c92b246db233ab05431c22ffffa7bc5091
2026-05-16 00:24:14.300302 : DEBUG_ARR: deleted: sha256:f03554f4869b0154163f9103c6b27335b295d7844a6a820d1c9c605866a32fd9
2026-05-16 00:24:14.300307 : DEBUG_ARR: deleted: sha256:95c6c0153730bf89349fe2804e5734593721f48b6ba859ec23e23de1b1eea563
2026-05-16 00:24:14.300311 : DEBUG_ARR: deleted: sha256:318ae74b22402f342c37731c92f614e980994991cfd904e6ca5bf3c2728bf0ee
2026-05-16 00:24:14.300314 : DEBUG_ARR: deleted: sha256:e286be8a15ac347e5338536ffc0157d96248d43b99c2a6fe26847be217faf841
2026-05-16 00:24:14.300317 : DEBUG_ARR: deleted: sha256:a32205164a8c2c265d4654a790f20c0eed53e201cba586def162a6e240fe48ff
2026-05-16 00:24:14.300320 : DEBUG_ARR: 
2026-05-16 00:24:14.300324 : DEBUG_ARR: Total reclaimed space: 535.3MB
2026-05-16 00:24:14.300622 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "cd ~/sonic-mgmt; ./setup-container.sh -n sonic-mgmt-test -d /data -v"
2026-05-16 00:27:52.021033 : DEBUG_ARR: NOTICE: using default docker image: sonicdev-microsoft.azurecr.io:443/docker-sonic-mgmt
2026-05-16 00:27:52.021073 : DEBUG_ARR: INFO: read SSH public key: /home/ubuntu/.ssh/id_rsa_docker_sonic_mgmt.pub
2026-05-16 00:27:52.021077 : DEBUG_ARR: INFO: setup a temporary dir: /tmp/tmp.Shux9ua2Ad
2026-05-16 00:27:52.021081 : DEBUG_ARR: INFO: copy SSH key pair: id_rsa_docker_sonic_mgmt/id_rsa_docker_sonic_mgmt.pub
2026-05-16 00:27:52.021084 : DEBUG_ARR: '/home/ubuntu/.ssh/id_rsa_docker_sonic_mgmt' -> '/tmp/tmp.Shux9ua2Ad/id_rsa'
2026-05-16 00:27:52.021087 : DEBUG_ARR: '/home/ubuntu/.ssh/id_rsa_docker_sonic_mgmt.pub' -> '/tmp/tmp.Shux9ua2Ad/id_rsa.pub'
2026-05-16 00:27:52.021090 : DEBUG_ARR: INFO: prepare a Dockerfile template: /tmp/tmp.Shux9ua2Ad/Dockerfile.j2
2026-05-16 00:27:52.021093 : DEBUG_ARR: INFO: prepare an environment file: /tmp/tmp.Shux9ua2Ad/data.env
2026-05-16 00:27:52.021098 : DEBUG_ARR: INFO: generate a Dockerfile: /tmp/tmp.Shux9ua2Ad/Dockerfile
2026-05-16 00:27:52.021101 : DEBUG_ARR: INFO: building docker image from /tmp/tmp.Shux9ua2Ad: docker-sonic-mgmt-ubuntu:master ...
2026-05-16 00:27:52.021104 : DEBUG_ARR: DEPRECATED: The legacy builder is deprecated and will be removed in a future release.
2026-05-16 00:27:52.021107 : DEBUG_ARR:             Install the buildx component to build images with BuildKit:
2026-05-16 00:27:52.021110 : DEBUG_ARR:             https://docs.docker.com/go/buildx/
2026-05-16 00:27:52.021113 : DEBUG_ARR: 
2026-05-16 00:27:52.021116 : DEBUG_ARR: Sending build context to Docker daemon  15.36kB
2026-05-16 00:27:52.021119 : DEBUG_ARR: 
2026-05-16 00:27:52.021122 : DEBUG_ARR: Step 1/26 : FROM sonicdev-microsoft.azurecr.io:443/docker-sonic-mgmt
2026-05-16 00:27:52.021126 : DEBUG_ARR:  ---> 0c6bcf119fc8
2026-05-16 00:27:52.021129 : DEBUG_ARR: Step 2/26 : USER root
2026-05-16 00:27:52.021132 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021135 : DEBUG_ARR:  ---> 8999f4040729
2026-05-16 00:27:52.021138 : DEBUG_ARR: Step 3/26 : RUN if getent group ubuntu; then groupmod -o -g 1000 ubuntu; else groupadd -o -g 1000 ubuntu; fi
2026-05-16 00:27:52.021143 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021146 : DEBUG_ARR:  ---> a2d4c2f72772
2026-05-16 00:27:52.021149 : DEBUG_ARR: Step 4/26 : RUN if getent passwd ubuntu; then userdel ubuntu; fi
2026-05-16 00:27:52.021152 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021158 : DEBUG_ARR:  ---> 45011e85c0f8
2026-05-16 00:27:52.021161 : DEBUG_ARR: Step 5/26 : RUN useradd -o -l -g 1000 -u 1000 -m -d /home/ubuntu -s /bin/bash ubuntu;
2026-05-16 00:27:52.021164 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021167 : DEBUG_ARR:  ---> 1368fe9ba835
2026-05-16 00:27:52.021170 : DEBUG_ARR: Step 6/26 : RUN if getent group docker; then groupmod -o -g 120 docker; else groupadd -o -g 120 docker; fi
2026-05-16 00:27:52.021174 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021177 : DEBUG_ARR:  ---> 0b7cd958511b
2026-05-16 00:27:52.021181 : DEBUG_ARR: Step 7/26 : RUN if [ 'ubuntu' != 'AzDevOps' ]; then /bin/bash -O extglob -c 'cp -a -f /var/AzDevOps/!(env-*) /home/ubuntu/'; for hidden_stuff in '.profile .local .ssh'; do /bin/bash -c 'cp -a -f /var/AzDevOps/$hidden_stuff /home/ubuntu/ || true'; done fi
2026-05-16 00:27:52.021187 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021190 : DEBUG_ARR:  ---> bdaa22f28047
2026-05-16 00:27:52.021193 : DEBUG_ARR: Step 8/26 : RUN usermod -a -G sudo ubuntu
2026-05-16 00:27:52.021196 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021199 : DEBUG_ARR:  ---> 4cb207ac802b
2026-05-16 00:27:52.021203 : DEBUG_ARR: Step 9/26 : RUN usermod -a -G docker ubuntu
2026-05-16 00:27:52.021206 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021209 : DEBUG_ARR:  ---> 13afb2c43198
2026-05-16 00:27:52.021212 : DEBUG_ARR: Step 10/26 : RUN echo 'ubuntu ALL=(ALL) NOPASSWD:ALL' > /etc/sudoers.d/ubuntu
2026-05-16 00:27:52.021215 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021218 : DEBUG_ARR:  ---> fd1409b34b8d
2026-05-16 00:27:52.021221 : DEBUG_ARR: Step 11/26 : RUN chmod 0440 /etc/sudoers.d/ubuntu
2026-05-16 00:27:52.021224 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021227 : DEBUG_ARR:  ---> dd6caf951fe5
2026-05-16 00:27:52.021230 : DEBUG_ARR: Step 12/26 : RUN chown -R '1000:1000' /home/ubuntu
2026-05-16 00:27:52.021233 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021236 : DEBUG_ARR:  ---> e79af252f823
2026-05-16 00:27:52.021293 : DEBUG_ARR: Step 13/26 : RUN sed -i -E 's/^#?PermitRootLogin.*$/PermitRootLogin yes/g' /etc/ssh/sshd_config
2026-05-16 00:27:52.021299 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021302 : DEBUG_ARR:  ---> bddd8de75ba6
2026-05-16 00:27:52.021305 : DEBUG_ARR: Step 14/26 : RUN echo 'root:root' | chpasswd
2026-05-16 00:27:52.021308 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021311 : DEBUG_ARR:  ---> 3b06de70a506
2026-05-16 00:27:52.021314 : DEBUG_ARR: Step 15/26 : RUN echo 'ubuntu:12345' | chpasswd
2026-05-16 00:27:52.021317 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021320 : DEBUG_ARR:  ---> efba30a8da09
2026-05-16 00:27:52.021323 : DEBUG_ARR: Step 16/26 : USER ubuntu
2026-05-16 00:27:52.021326 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021329 : DEBUG_ARR:  ---> cb0d451ddaf7
2026-05-16 00:27:52.021332 : DEBUG_ARR: Step 17/26 : ENV HOME=/home/ubuntu
2026-05-16 00:27:52.021335 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021338 : DEBUG_ARR:  ---> 593563140b4b
2026-05-16 00:27:52.021341 : DEBUG_ARR: Step 18/26 : ENV USER=ubuntu
2026-05-16 00:27:52.021344 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021347 : DEBUG_ARR:  ---> 702c7785b3ca
2026-05-16 00:27:52.021352 : DEBUG_ARR: Step 19/26 : COPY --chown=1000:1000 id_rsa id_rsa.pub ${HOME}/.ssh/
2026-05-16 00:27:52.021355 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021358 : DEBUG_ARR:  ---> 2acceb0ea3b7
2026-05-16 00:27:52.021361 : DEBUG_ARR: Step 20/26 : RUN chmod 0700 ${HOME}/.ssh
2026-05-16 00:27:52.021364 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021367 : DEBUG_ARR:  ---> aa8e43f1477f
2026-05-16 00:27:52.021370 : DEBUG_ARR: Step 21/26 : RUN chmod 0600 ${HOME}/.ssh/id_rsa
2026-05-16 00:27:52.021373 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021376 : DEBUG_ARR:  ---> 267823550bc7
2026-05-16 00:27:52.021379 : DEBUG_ARR: Step 22/26 : RUN chmod 0644 ${HOME}/.ssh/id_rsa.pub
2026-05-16 00:27:52.021382 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021385 : DEBUG_ARR:  ---> d6adcc78ffff
2026-05-16 00:27:52.021388 : DEBUG_ARR: Step 23/26 : RUN cat ${HOME}/.ssh/id_rsa.pub >> ${HOME}/.ssh/authorized_keys
2026-05-16 00:27:52.021391 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021394 : DEBUG_ARR:  ---> 3d3d2655a7f0
2026-05-16 00:27:52.021397 : DEBUG_ARR: Step 24/26 : RUN chmod 0600 ${HOME}/.ssh/authorized_keys
2026-05-16 00:27:52.021400 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021403 : DEBUG_ARR:  ---> b626369daccd
2026-05-16 00:27:52.021406 : DEBUG_ARR: Step 25/26 : WORKDIR ${HOME}
2026-05-16 00:27:52.021409 : DEBUG_ARR:  ---> Using cache
2026-05-16 00:27:52.021412 : DEBUG_ARR:  ---> bb450819555d
2026-05-16 00:27:52.021415 : DEBUG_ARR: Step 26/26 : RUN if ! pip3 list | grep -c pytest >/dev/null && [ 'ubuntu' != 'AzDevOps' ] && [ -d /var/AzDevOps/env-python3 ]; then /bin/bash -c 'python3 -m venv ${HOME}/env-python3'; /bin/bash -c "${HOME}/env-python3/bin/pip install  -i https://mirrors.aliyun.com/pypi/simple/ --upgrade 'pip<24.1'"; /bin/bash -c '${HOME}/env-python3/bin/pip install  -i https://mirrors.aliyun.com/pypi/simple/ wheel'; /bin/bash -c '${HOME}/env-python3/bin/pip  install  -i https://mirrors.aliyun.com/pypi/simple/ --upgrade paramiko'; /bin/bash -c '${HOME}/env-python3/bin/pip install  -i https://mirrors.aliyun.com/pypi/simple/ $(/var/AzDevOps/env-python3/bin/pip freeze | grep -vE "distro|PyGObject|python-apt|unattended-upgrades|dbus-python")'; fi
2026-05-16 00:27:52.021419 : DEBUG_ARR:  ---> Running in 9e992c24ecae
2026-05-16 00:27:52.021422 : DEBUG_ARR: Looking in indexes: https://mirrors.aliyun.com/pypi/simple/
2026-05-16 00:27:52.021425 : DEBUG_ARR: Collecting pip<24.1
2026-05-16 00:27:52.021428 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/8a/6a/19e9fe04fca059ccf770861c7d5721ab4c2aebc539889e97c7977528a53b/pip-24.0-py3-none-any.whl (2.1 MB)
2026-05-16 00:27:52.021431 : DEBUG_ARR: Installing collected packages: pip
2026-05-16 00:27:52.021434 : DEBUG_ARR:   Attempting uninstall: pip
2026-05-16 00:27:52.021437 : DEBUG_ARR:     Found existing installation: pip 20.0.2
2026-05-16 00:27:52.021440 : DEBUG_ARR:     Uninstalling pip-20.0.2:
2026-05-16 00:27:52.021443 : DEBUG_ARR:       Successfully uninstalled pip-20.0.2
2026-05-16 00:27:52.021446 : DEBUG_ARR: Successfully installed pip-24.0
2026-05-16 00:27:52.021449 : DEBUG_ARR: Looking in indexes: https://mirrors.aliyun.com/pypi/simple/
2026-05-16 00:27:52.021452 : DEBUG_ARR: Collecting wheel
2026-05-16 00:27:52.021455 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/0b/2c/87f3254fd8ffd29e4c02732eee68a83a1d3c346ae39bc6822dcbcb697f2b/wheel-0.45.1-py3-none-any.whl (72 kB)
2026-05-16 00:27:52.021459 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 72.5/72.5 kB 284.2 kB/s eta 0:00:00
2026-05-16 00:27:52.021464 : DEBUG_ARR: Installing collected packages: wheel
2026-05-16 00:27:52.021467 : DEBUG_ARR: Successfully installed wheel-0.45.1
2026-05-16 00:27:52.021470 : DEBUG_ARR: [91m
2026-05-16 00:27:52.021473 : DEBUG_ARR: [notice] A new release of pip is available: 24.0 -> 25.0.1
2026-05-16 00:27:52.021476 : DEBUG_ARR: [notice] To update, run: python3 -m pip install --upgrade pip
2026-05-16 00:27:52.021479 : DEBUG_ARR: [0mLooking in indexes: https://mirrors.aliyun.com/pypi/simple/
2026-05-16 00:27:52.021482 : DEBUG_ARR: Collecting paramiko
2026-05-16 00:27:52.021485 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/15/f8/c7bd0ef12954a81a1d3cea60a13946bd9a49a0036a5927770c461eade7ae/paramiko-3.5.1-py3-none-any.whl (227 kB)
2026-05-16 00:27:52.021488 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 227.3/227.3 kB 175.4 kB/s eta 0:00:00
2026-05-16 00:27:52.021492 : DEBUG_ARR: Collecting bcrypt>=3.2 (from paramiko)
2026-05-16 00:27:52.021495 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/0f/c3/0ae57a68be2039287ec28bc463b82e4b8dc23f9d12c0be331f4782e19108/bcrypt-5.0.0-cp38-abi3-manylinux_2_28_x86_64.whl (278 kB)
2026-05-16 00:27:52.021498 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 278.4/278.4 kB 147.2 kB/s eta 0:00:00
2026-05-16 00:27:52.021502 : DEBUG_ARR: Collecting cryptography>=3.3 (from paramiko)
2026-05-16 00:27:52.021505 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/7e/b8/ac57107ef32749d2b244e36069bb688792a363aaaa3acc9e3cf84c130315/cryptography-47.0.0-cp38-abi3-manylinux_2_28_x86_64.whl (4.7 MB)
2026-05-16 00:27:52.021508 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 4.7/4.7 MB 227.3 kB/s eta 0:00:00
2026-05-16 00:27:52.021511 : DEBUG_ARR: Collecting pynacl>=1.5 (from paramiko)
2026-05-16 00:27:52.021514 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/3e/d0/f301f83ac8dbe53442c5a43f6a39016f94f754d7a9815a875b65e218a307/pynacl-1.6.2-cp38-abi3-manylinux_2_26_x86_64.manylinux_2_28_x86_64.whl (1.4 MB)
2026-05-16 00:27:52.021517 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.4/1.4 MB 430.0 kB/s eta 0:00:00
2026-05-16 00:27:52.021521 : DEBUG_ARR: Collecting cffi>=1.14 (from cryptography>=3.3->paramiko)
2026-05-16 00:27:52.021524 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/bb/19/b51af9f4a4faa4a8ac5a0e5d5c2522dcd9703d07fac69da34a36c4d960d3/cffi-1.17.1-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (446 kB)
2026-05-16 00:27:52.021527 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 446.5/446.5 kB 533.6 kB/s eta 0:00:00
2026-05-16 00:27:52.021530 : DEBUG_ARR: Collecting typing-extensions>=4.13.2 (from cryptography>=3.3->paramiko)
2026-05-16 00:27:52.021533 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/8b/54/b1ae86c0973cc6f0210b53d508ca3641fb6d0c56823f288d108bc7ab3cc8/typing_extensions-4.13.2-py3-none-any.whl (45 kB)
2026-05-16 00:27:52.021555 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 45.8/45.8 kB 1.7 MB/s eta 0:00:00
2026-05-16 00:27:52.021560 : DEBUG_ARR: Collecting pycparser (from cffi>=1.14->cryptography>=3.3->paramiko)
2026-05-16 00:27:52.021563 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/a0/e3/59cd50310fc9b59512193629e1984c1f95e5c8ae6e5d8c69532ccc65a7fe/pycparser-2.23-py3-none-any.whl (118 kB)
2026-05-16 00:27:52.021566 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 118.1/118.1 kB 3.4 MB/s eta 0:00:00
2026-05-16 00:27:52.021570 : DEBUG_ARR: Installing collected packages: typing-extensions, pycparser, bcrypt, cffi, pynacl, cryptography, paramiko
2026-05-16 00:27:52.021573 : DEBUG_ARR: Successfully installed bcrypt-5.0.0 cffi-1.17.1 cryptography-47.0.0 paramiko-3.5.1 pycparser-2.23 pynacl-1.6.2 typing-extensions-4.13.2
2026-05-16 00:27:52.021576 : DEBUG_ARR: [91m
2026-05-16 00:27:52.021579 : DEBUG_ARR: [notice] A new release of pip is available: 24.0 -> 25.0.1
2026-05-16 00:27:52.021582 : DEBUG_ARR: [notice] To update, run: python3 -m pip install --upgrade pip
2026-05-16 00:27:52.021585 : DEBUG_ARR: [0mLooking in indexes: https://mirrors.aliyun.com/pypi/simple/
2026-05-16 00:27:52.021588 : DEBUG_ARR: Collecting abstract-open-traffic-generator==0.0.68
2026-05-16 00:27:52.021591 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/21/1c/1c5e5ee6a05a098cdacdb826f247c2c8eb416ecefd006966e4ffd9d7d912/abstract_open_traffic_generator-0.0.68-py2.py3-none-any.whl (48 kB)
2026-05-16 00:27:52.021594 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 48.3/48.3 kB 538.2 kB/s eta 0:00:00
2026-05-16 00:27:52.021598 : DEBUG_ARR: Collecting aiohttp==3.8.4
2026-05-16 00:27:52.021601 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/d2/e5/cef5eeb11d7e8bac830b3bee1c8311b19bf8e8a1c45fe14b876c70adcd06/aiohttp-3.8.4-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (1.0 MB)
2026-05-16 00:27:52.021604 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.0/1.0 MB 981.6 kB/s eta 0:00:00
2026-05-16 00:27:52.021607 : DEBUG_ARR: Collecting aiosignal==1.3.1
2026-05-16 00:27:52.021610 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/76/ac/a7305707cb852b7e16ff80eaf5692309bde30e2b1100a1fcacdc8f731d97/aiosignal-1.3.1-py3-none-any.whl (7.6 kB)
2026-05-16 00:27:52.021614 : DEBUG_ARR: Collecting allure-pytest==2.8.22
2026-05-16 00:27:52.021617 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/88/39/d4bc2f810dfb0bfcde973f1a82491330663b04fd5c6fb48e9a113449f0e6/allure_pytest-2.8.22-py3-none-any.whl (9.5 kB)
2026-05-16 00:27:52.021620 : DEBUG_ARR: Collecting allure-python-commons==2.8.22
2026-05-16 00:27:52.021623 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/c9/18/cdb7305f81664b5bcc65a02329667e2e1728caaa46115d63af7592be3f72/allure_python_commons-2.8.22-py3-none-any.whl (15 kB)
2026-05-16 00:27:52.021626 : DEBUG_ARR: Collecting amqp==2.6.1
2026-05-16 00:27:52.021629 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/bc/90/bb5ce93521772f083cb2d7a413bb82eda5afc62b4192adb7ea4c7b4858b9/amqp-2.6.1-py2.py3-none-any.whl (48 kB)
2026-05-16 00:27:52.021632 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 48.0/48.0 kB 1.3 MB/s eta 0:00:00
2026-05-16 00:27:52.021635 : DEBUG_ARR: Collecting ansible==2.9.27
2026-05-16 00:27:52.021638 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/5b/99/ce005d0314840e1a6eef34e0faf0ba4f7bccd8172b33cc84fee21afab7ad/ansible-2.9.27.tar.gz (14.8 MB)
2026-05-16 00:27:52.021641 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 14.8/14.8 MB 1.1 MB/s eta 0:00:00
2026-05-16 00:27:52.021645 : DEBUG_ARR:   Preparing metadata (setup.py): started
2026-05-16 00:27:52.021648 : DEBUG_ARR:   Preparing metadata (setup.py): finished with status 'done'
2026-05-16 00:27:52.021651 : DEBUG_ARR: Collecting astroid==1.6.6
2026-05-16 00:27:52.021654 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/8b/29/0f7ec6fbf28a158886b7de49aee3a77a8a47a7e24c60e9fd6ec98ee2ec02/astroid-1.6.6-py2.py3-none-any.whl (305 kB)
2026-05-16 00:27:52.021657 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 305.6/305.6 kB 4.3 MB/s eta 0:00:00
2026-05-16 00:27:52.021660 : DEBUG_ARR: Collecting async-timeout==4.0.2
2026-05-16 00:27:52.021663 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/d6/c1/8991e7c5385b897b8c020cdaad718c5b087a6626d1d11a23e1ea87e325a7/async_timeout-4.0.2-py3-none-any.whl (5.8 kB)
2026-05-16 00:27:52.021666 : DEBUG_ARR: Collecting attrs==23.1.0
2026-05-16 00:27:52.021673 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/f0/eb/fcb708c7bf5056045e9e98f62b93bd7467eb718b0202e7698eb11d66416c/attrs-23.1.0-py3-none-any.whl (61 kB)
2026-05-16 00:27:52.021677 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 61.2/61.2 kB 1.7 MB/s eta 0:00:00
2026-05-16 00:27:52.021680 : DEBUG_ARR: Collecting azure-core==1.26.4
2026-05-16 00:27:52.021683 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/8d/12/8d1b124dcce9a695a8a8907461684ad08af4eca575e59fb2c8c70539caf7/azure_core-1.26.4-py3-none-any.whl (173 kB)
2026-05-16 00:27:52.021686 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 173.9/173.9 kB 6.4 MB/s eta 0:00:00
2026-05-16 00:27:52.021690 : DEBUG_ARR: Collecting azure-identity==1.12.0
2026-05-16 00:27:52.021693 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/ce/96/942f03d8a80e30e2289496c10d99e3a8b71f10c0b70b5337fd8ec2ae85e5/azure_identity-1.12.0-py3-none-any.whl (135 kB)
2026-05-16 00:27:52.021696 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 135.5/135.5 kB 5.3 MB/s eta 0:00:00
2026-05-16 00:27:52.021699 : DEBUG_ARR: Collecting azure-kusto-data==4.1.4
2026-05-16 00:27:52.021702 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/45/a7/6a0d837feb034e15a35b8bd82d9f5bdca609517b1aef9ba6f6236a22d0e4/azure_kusto_data-4.1.4-py2.py3-none-any.whl (53 kB)
2026-05-16 00:27:52.021705 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 53.2/53.2 kB 1.5 MB/s eta 0:00:00
2026-05-16 00:27:52.021708 : DEBUG_ARR: Collecting azure-kusto-ingest==4.1.4
2026-05-16 00:27:52.021711 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/78/5a/174bea70200b85096682aaf6f760a58dfa445c9b85787a80ec50febad79f/azure_kusto_ingest-4.1.4-py2.py3-none-any.whl (25 kB)
2026-05-16 00:27:52.021714 : DEBUG_ARR: Collecting azure-storage-blob==12.9.0
2026-05-16 00:27:52.021717 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/41/f3/e2b3fa9de629ab76031588daf54b4c28d71bd3c209d8a3d4f470d87e98a7/azure_storage_blob-12.9.0-py2.py3-none-any.whl (356 kB)
2026-05-16 00:27:52.021720 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 356.5/356.5 kB 9.0 MB/s eta 0:00:00
2026-05-16 00:27:52.021724 : DEBUG_ARR: Collecting azure-storage-queue==12.6.0
2026-05-16 00:27:52.021727 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/10/a5/970149b9357d1ae1578fa3650fa9348a47b2e113f651d47398f156c4f908/azure_storage_queue-12.6.0-py3-none-any.whl (170 kB)
2026-05-16 00:27:52.021744 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 170.9/170.9 kB 3.2 MB/s eta 0:00:00
2026-05-16 00:27:52.021748 : DEBUG_ARR: Collecting bcrypt==4.0.1
2026-05-16 00:27:52.021751 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/64/fe/da28a5916128d541da0993328dc5cf4b43dfbf6655f2c7a2abe26ca2dc88/bcrypt-4.0.1-cp36-abi3-manylinux_2_28_x86_64.whl (593 kB)
2026-05-16 00:27:52.021754 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 593.7/593.7 kB 1.4 MB/s eta 0:00:00
2026-05-16 00:27:52.021757 : DEBUG_ARR: Collecting billiard==3.6.4.0
2026-05-16 00:27:52.021761 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/2b/89/0c43de91d4e52eaa7bd748771d417f6ac9e51e66b2f61928c2151bf65878/billiard-3.6.4.0-py3-none-any.whl (89 kB)
2026-05-16 00:27:52.021764 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 89.5/89.5 kB 6.2 MB/s eta 0:00:00
2026-05-16 00:27:52.021767 : DEBUG_ARR: Collecting celery==4.4.7
2026-05-16 00:27:52.021770 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/c8/0c/609e3611d20c9f8d883852d1be5516671f630fb08c8c1e56911567dfba7b/celery-4.4.7-py2.py3-none-any.whl (427 kB)
2026-05-16 00:27:52.021773 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 427.6/427.6 kB 8.1 MB/s eta 0:00:00
2026-05-16 00:27:52.021777 : DEBUG_ARR: Collecting certifi==2022.12.7
2026-05-16 00:27:52.021780 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/71/4c/3db2b8021bd6f2f0ceb0e088d6b2d49147671f25832fb17970e9b583d742/certifi-2022.12.7-py3-none-any.whl (155 kB)
2026-05-16 00:27:52.021783 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 155.3/155.3 kB 2.6 MB/s eta 0:00:00
2026-05-16 00:27:52.021786 : DEBUG_ARR: Collecting cffi==1.15.1
2026-05-16 00:27:52.021789 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/b7/8b/06f30caa03b5b3ac006de4f93478dbd0239e2a16566d81a106c322dc4f79/cffi-1.15.1-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (442 kB)
2026-05-16 00:27:52.021792 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 442.7/442.7 kB 10.8 MB/s eta 0:00:00
2026-05-16 00:27:52.021796 : DEBUG_ARR: Collecting charset-normalizer==3.1.0
2026-05-16 00:27:52.021799 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/74/5f/361202de730532028458b729781b8435f320e31a622c27f30e25eec80513/charset_normalizer-3.1.0-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (195 kB)
2026-05-16 00:27:52.021802 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 195.9/195.9 kB 7.1 MB/s eta 0:00:00
2026-05-16 00:27:52.021805 : DEBUG_ARR: Collecting contextlib2==0.6.0.post1
2026-05-16 00:27:52.021808 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/85/60/370352f7ef6aa96c52fb001831622f50f923c1d575427d021b8ab3311236/contextlib2-0.6.0.post1-py2.py3-none-any.whl (9.8 kB)
2026-05-16 00:27:52.021811 : DEBUG_ARR: Collecting cryptography==3.3.2
2026-05-16 00:27:52.021814 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/c6/d1/800ec785c9e66cc6d0ac587bd666eb22f7b2ff6c150e053d35881acd2f57/cryptography-3.3.2-cp36-abi3-manylinux2010_x86_64.whl (2.6 MB)
2026-05-16 00:27:52.021817 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 2.6/2.6 MB 1.2 MB/s eta 0:00:00
2026-05-16 00:27:52.021821 : DEBUG_ARR: Collecting decorator==5.1.1
2026-05-16 00:27:52.021824 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/d5/50/83c593b07763e1161326b3b8c6686f0f4b0f24d5526546bee538c89837d6/decorator-5.1.1-py3-none-any.whl (9.1 kB)
2026-05-16 00:27:52.021827 : DEBUG_ARR: Collecting defusedxml==0.7.1
2026-05-16 00:27:52.021830 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/07/6c/aa3f2f849e01cb6a001cd8554a88d4c77c5c1a31c95bdf1cf9301e6d9ef4/defusedxml-0.7.1-py2.py3-none-any.whl (25 kB)
2026-05-16 00:27:52.021833 : DEBUG_ARR: Collecting distlib==0.3.6
2026-05-16 00:27:52.021836 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/76/cb/6bbd2b10170ed991cf64e8c8b85e01f2fb38f95d1bc77617569e0b0b26ac/distlib-0.3.6-py2.py3-none-any.whl (468 kB)
2026-05-16 00:27:52.021839 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 468.5/468.5 kB 10.7 MB/s eta 0:00:00
2026-05-16 00:27:52.021842 : DEBUG_ARR: Collecting dpkt==1.9.8
2026-05-16 00:27:52.021845 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/11/79/479e2194c9096b92aecdf33634ae948d2be306c6011673e98ee1917f32c2/dpkt-1.9.8-py3-none-any.whl (194 kB)
2026-05-16 00:27:52.021849 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 195.0/195.0 kB 6.7 MB/s eta 0:00:00
2026-05-16 00:27:52.021852 : DEBUG_ARR: Collecting execnet==1.9.0
2026-05-16 00:27:52.021855 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/81/c0/3072ecc23f4c5e0a1af35e3a222855cfd9c80a1a105ca67be3b6172637dd/execnet-1.9.0-py2.py3-none-any.whl (39 kB)
2026-05-16 00:27:52.021858 : DEBUG_ARR: Collecting filelock==3.12.0
2026-05-16 00:27:52.021861 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/ad/73/b094a662ae05cdc4ec95bc54e434e307986a5de5960166b8161b7c1373ee/filelock-3.12.0-py3-none-any.whl (10 kB)
2026-05-16 00:27:52.021864 : DEBUG_ARR: Collecting frozenlist==1.3.3
2026-05-16 00:27:52.021867 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/ec/ab/a440db757401a1e8863c9abb374a77cb2884eda74ffbf555dedcf1fbe7f6/frozenlist-1.3.3-cp38-cp38-manylinux_2_5_x86_64.manylinux1_x86_64.manylinux_2_17_x86_64.manylinux2014_x86_64.whl (161 kB)
2026-05-16 00:27:52.021873 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 161.3/161.3 kB 355.6 kB/s eta 0:00:00
2026-05-16 00:27:52.021876 : DEBUG_ARR: Collecting future==0.18.3
2026-05-16 00:27:52.021879 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/8f/2e/cf6accf7415237d6faeeebdc7832023c90e0282aa16fd3263db0eb4715ec/future-0.18.3.tar.gz (840 kB)
2026-05-16 00:27:52.021882 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 840.9/840.9 kB 1.6 MB/s eta 0:00:00
2026-05-16 00:27:52.021885 : DEBUG_ARR:   Preparing metadata (setup.py): started
2026-05-16 00:27:52.021888 : DEBUG_ARR:   Preparing metadata (setup.py): finished with status 'done'
2026-05-16 00:27:52.021891 : DEBUG_ARR: Collecting gitdb==4.0.10
2026-05-16 00:27:52.021894 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/21/a6/35f83efec687615c711fe0a09b67e58f6d1254db27b1013119de46f450bd/gitdb-4.0.10-py3-none-any.whl (62 kB)
2026-05-16 00:27:52.021897 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 62.7/62.7 kB 35.4 kB/s eta 0:00:00
2026-05-16 00:27:52.021901 : DEBUG_ARR: Collecting GitPython==3.1.31
2026-05-16 00:27:52.021904 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/9e/8a/d1e02cc111d65b0346f70abb83c51f8593e7134bf694a4a56d1a470caaf7/GitPython-3.1.31-py3-none-any.whl (184 kB)
2026-05-16 00:27:52.021907 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 184.3/184.3 kB 458.5 kB/s eta 0:00:00
2026-05-16 00:27:52.021926 : DEBUG_ARR: Collecting grpcio==1.44.0
2026-05-16 00:27:52.021930 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/5b/92/a00eed89bae16e48644f514c842b1cc6deaf0f79cb7dcfeda2dc514e11af/grpcio-1.44.0-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (4.3 MB)
2026-05-16 00:27:52.021933 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 4.3/4.3 MB 2.4 MB/s eta 0:00:00
2026-05-16 00:27:52.021937 : DEBUG_ARR: Collecting grpcio-tools==1.44.0
2026-05-16 00:27:52.021940 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/0c/ab/6bc77bb47dc8b950c4957553fbb3d040be0b3d16ff2fe44bef0a5cbac7a6/grpcio_tools-1.44.0-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (2.4 MB)
2026-05-16 00:27:52.021943 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 2.4/2.4 MB 2.1 MB/s eta 0:00:00
2026-05-16 00:27:52.021946 : DEBUG_ARR: Collecting idna==3.4
2026-05-16 00:27:52.021950 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/fc/34/3030de6f1370931b9dbb4dad48f6ab1015ab1d32447850b9fc94e60097be/idna-3.4-py3-none-any.whl (61 kB)
2026-05-16 00:27:52.021953 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 61.5/61.5 kB 1.1 MB/s eta 0:00:00
2026-05-16 00:27:52.021956 : DEBUG_ARR: Collecting ijson==3.2.0.post0
2026-05-16 00:27:52.021959 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/41/81/7dcbdc2ae5d29540f5f9fb4a528003675b0079ada3a9f38e9e79f35a5584/ijson-3.2.0.post0-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (114 kB)
2026-05-16 00:27:52.021962 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 114.8/114.8 kB 4.5 MB/s eta 0:00:00
2026-05-16 00:27:52.021966 : DEBUG_ARR: Collecting iniconfig==2.0.0
2026-05-16 00:27:52.021969 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/ef/a6/62565a6e1cf69e10f5727360368e451d4b7f58beeac6173dc9db836a5b46/iniconfig-2.0.0-py3-none-any.whl (5.9 kB)
2026-05-16 00:27:52.021972 : DEBUG_ARR: Collecting ipaddr==2.2.0
2026-05-16 00:27:52.021975 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/9d/a7/1b39a16cb90dfe491f57e1cab3103a15d4e8dd9a150872744f531b1106c1/ipaddr-2.2.0.tar.gz (26 kB)
2026-05-16 00:27:52.021978 : DEBUG_ARR:   Preparing metadata (setup.py): started
2026-05-16 00:27:52.021981 : DEBUG_ARR:   Preparing metadata (setup.py): finished with status 'done'
2026-05-16 00:27:52.021984 : DEBUG_ARR: Collecting ipython==5.4.1
2026-05-16 00:27:52.021987 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/3d/f0/3770e603de61f62bc9f1935305daf0a66ec2e699b8617d466cc47803f5ba/ipython-5.4.1-py3-none-any.whl (757 kB)
2026-05-16 00:27:52.021990 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 757.6/757.6 kB 7.0 MB/s eta 0:00:00
2026-05-16 00:27:52.021993 : DEBUG_ARR: Collecting isodate==0.6.1
2026-05-16 00:27:52.021996 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/b6/85/7882d311924cbcfc70b1890780763e36ff0b140c7e51c110fc59a532f087/isodate-0.6.1-py2.py3-none-any.whl (41 kB)
2026-05-16 00:27:52.021999 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 41.7/41.7 kB 79.6 kB/s eta 0:00:00
2026-05-16 00:27:52.022003 : DEBUG_ARR: Collecting isort==5.12.0
2026-05-16 00:27:52.022006 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/0a/63/4036ae70eea279c63e2304b91ee0ac182f467f24f86394ecfe726092340b/isort-5.12.0-py3-none-any.whl (91 kB)
2026-05-16 00:27:52.022009 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 91.2/91.2 kB 1.8 MB/s eta 0:00:00
2026-05-16 00:27:52.022012 : DEBUG_ARR: Collecting ixnetwork-open-traffic-generator==0.0.79
2026-05-16 00:27:52.022016 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/8f/aa/dc5a95a3544a60a089eb51a0f23f5fb1e29aaa936f72ba2876c7add3551d/ixnetwork_open_traffic_generator-0.0.79-py2.py3-none-any.whl (46 kB)
2026-05-16 00:27:52.022019 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 46.4/46.4 kB 1.2 MB/s eta 0:00:00
2026-05-16 00:27:52.022022 : DEBUG_ARR: Collecting ixnetwork-restpy==1.0.64
2026-05-16 00:27:52.022026 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/43/26/2c5a1215c79e7776d7db10dff687953127b21c2a28b56bacbbe822abcf60/ixnetwork_restpy-1.0.64-py2.py3-none-any.whl (8.4 MB)
2026-05-16 00:27:52.022029 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 8.4/8.4 MB 6.4 MB/s eta 0:00:00
2026-05-16 00:27:52.022032 : DEBUG_ARR: Collecting Jinja2==2.10.1
2026-05-16 00:27:52.022035 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/1d/e7/fd8b501e7a6dfe492a433deb7b9d833d39ca74916fa8bc63dd1a4947a671/Jinja2-2.10.1-py2.py3-none-any.whl (124 kB)
2026-05-16 00:27:52.022038 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 124.9/124.9 kB 1.2 MB/s eta 0:00:00
2026-05-16 00:27:52.022041 : DEBUG_ARR: Collecting jsonpatch==1.32
2026-05-16 00:27:52.022044 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/a3/55/f7c93bae36d869292aedfbcbae8b091386194874f16390d680136edd2b28/jsonpatch-1.32-py2.py3-none-any.whl (12 kB)
2026-05-16 00:27:52.022047 : DEBUG_ARR: Collecting jsonpath-ng==1.5.3
2026-05-16 00:27:52.022050 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/4c/b7/3627068d9aa6b2d49af117eb3897770a5dbc6bb3f4c09ed56a9eb749438e/jsonpath_ng-1.5.3-py3-none-any.whl (29 kB)
2026-05-16 00:27:52.022053 : DEBUG_ARR: Collecting jsonpointer==2.3
2026-05-16 00:27:52.022056 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/a3/be/8dc9d31b50e38172c8020c40f497ce8debdb721545ddb9fcb7cca89ea9e6/jsonpointer-2.3-py2.py3-none-any.whl (7.8 kB)
2026-05-16 00:27:52.022059 : DEBUG_ARR: Collecting kombu==4.6.11
2026-05-16 00:27:52.022062 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/9e/34/3eea6a3a9ff81b0c7ddbdceb22a1ffc1b5907d863f27ca19a68777d2211d/kombu-4.6.11-py2.py3-none-any.whl (184 kB)
2026-05-16 00:27:52.022065 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 184.4/184.4 kB 4.8 MB/s eta 0:00:00
2026-05-16 00:27:52.022069 : DEBUG_ARR: Collecting lazy-object-proxy==1.9.0
2026-05-16 00:27:52.022072 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/4e/cb/aca3f4d89d3efbed724fd9504a96dafbe2d903ea908355a335acb110a5cd/lazy_object_proxy-1.9.0-cp38-cp38-manylinux_2_5_x86_64.manylinux1_x86_64.manylinux_2_17_x86_64.manylinux2014_x86_64.whl (61 kB)
2026-05-16 00:27:52.022078 : DEBUG_ARR:      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 61.4/61.4 kB 2.3 MB/s eta 0:00:00
2026-05-16 00:27:52.022081 : DEBUG_ARR: Collecting lxml==4.9.2
2026-05-16 00:27:52.022084 : DEBUG_ARR:   Downloading https://mirrors.aliyun.com/pypi/packages/3f/2f/8379eb85d10f06c01cab2b8a93fe676b6d7234e43441b17d348fdc735420/lxml-4.9.2-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.manylinux_2_24_x86_64.whl (7.1 MB)
2026-05-16 00:27:52.022087 : DEBUG_ARR:                                               0.0/7.1 MB 101.3 MB/s eta 0:00:01
2026-05-16 00:27:52.022090 : DEBUG_ARR: [91mERROR: Exception:
2026-05-16 00:27:52.022093 : DEBUG_ARR: Traceback (most recent call last):
2026-05-16 00:27:52.022110 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/urllib3/response.py", line 438, in _error_catcher
2026-05-16 00:27:52.022114 : DEBUG_ARR:     yield
2026-05-16 00:27:52.022117 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/urllib3/response.py", line 561, in read
2026-05-16 00:27:52.022120 : DEBUG_ARR:     data = self._fp_read(amt) if not fp_closed else b""
2026-05-16 00:27:52.022123 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/urllib3/response.py", line 527, in _fp_read
2026-05-16 00:27:52.022126 : DEBUG_ARR:     return self._fp.read(amt) if amt is not None else self._fp.read()
2026-05-16 00:27:52.022129 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/cachecontrol/filewrapper.py", line 98, in read
2026-05-16 00:27:52.022132 : DEBUG_ARR:     data: bytes = self.__fp.read(amt)
2026-05-16 00:27:52.022135 : DEBUG_ARR:   File "/usr/lib/python3.8/http/client.py", line 459, in read
2026-05-16 00:27:52.022138 : DEBUG_ARR:     n = self.readinto(b)
2026-05-16 00:27:52.022141 : DEBUG_ARR:   File "/usr/lib/python3.8/http/client.py", line 503, in readinto
2026-05-16 00:27:52.022144 : DEBUG_ARR:     n = self.fp.readinto(b)
2026-05-16 00:27:52.022147 : DEBUG_ARR:   File "/usr/lib/python3.8/socket.py", line 669, in readinto
2026-05-16 00:27:52.022150 : DEBUG_ARR:     return self._sock.recv_into(b)
2026-05-16 00:27:52.022153 : DEBUG_ARR:   File "/usr/lib/python3.8/ssl.py", line 1241, in recv_into
2026-05-16 00:27:52.022156 : DEBUG_ARR:     return self.read(nbytes, buffer)
2026-05-16 00:27:52.022159 : DEBUG_ARR:   File "/usr/lib/python3.8/ssl.py", line 1099, in read
2026-05-16 00:27:52.022162 : DEBUG_ARR:     return self._sslobj.read(len, buffer)
2026-05-16 00:27:52.022165 : DEBUG_ARR: socket.timeout: The read operation timed out
2026-05-16 00:27:52.022168 : DEBUG_ARR: 
2026-05-16 00:27:52.022171 : DEBUG_ARR: During handling of the above exception, another exception occurred:
2026-05-16 00:27:52.022174 : DEBUG_ARR: 
2026-05-16 00:27:52.022177 : DEBUG_ARR: Traceback (most recent call last):
2026-05-16 00:27:52.022180 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/cli/base_command.py", line 180, in exc_logging_wrapper
2026-05-16 00:27:52.022183 : DEBUG_ARR:     status = run_func(*args)
2026-05-16 00:27:52.022186 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/cli/req_command.py", line 245, in wrapper
2026-05-16 00:27:52.022189 : DEBUG_ARR:     return func(self, options, args)
2026-05-16 00:27:52.022192 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/commands/install.py", line 377, in run
2026-05-16 00:27:52.022195 : DEBUG_ARR:     requirement_set = resolver.resolve(
2026-05-16 00:27:52.022198 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/resolver.py", line 95, in resolve
2026-05-16 00:27:52.022201 : DEBUG_ARR:     result = self._result = resolver.resolve(
2026-05-16 00:27:52.022204 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/resolvelib/resolvers.py", line 546, in resolve
2026-05-16 00:27:52.022207 : DEBUG_ARR:     state = resolution.resolve(requirements, max_rounds=max_rounds)
2026-05-16 00:27:52.022210 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/resolvelib/resolvers.py", line 397, in resolve
2026-05-16 00:27:52.022213 : DEBUG_ARR:     self._add_to_criteria(self.state.criteria, r, parent=None)
2026-05-16 00:27:52.022216 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/resolvelib/resolvers.py", line 173, in _add_to_criteria
2026-05-16 00:27:52.022219 : DEBUG_ARR:     if not criterion.candidates:
2026-05-16 00:27:52.022222 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/resolvelib/structs.py", line 156, in __bool__
2026-05-16 00:27:52.022225 : DEBUG_ARR:     return bool(self._sequence)
2026-05-16 00:27:52.022228 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/found_candidates.py", line 155, in __bool__
2026-05-16 00:27:52.022231 : DEBUG_ARR:     return any(self)
2026-05-16 00:27:52.022234 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/found_candidates.py", line 143, in <genexpr>
2026-05-16 00:27:52.022237 : DEBUG_ARR:     return (c for c in iterator if id(c) not in self._incompatible_ids)
2026-05-16 00:27:52.022240 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/found_candidates.py", line 47, in _iter_built
2026-05-16 00:27:52.022243 : DEBUG_ARR:     candidate = func()
2026-05-16 00:27:52.022246 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/factory.py", line 182, in _make_candidate_from_link
2026-05-16 00:27:52.022249 : DEBUG_ARR:     base: Optional[BaseCandidate] = self._make_base_candidate_from_link(
2026-05-16 00:27:52.022252 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/factory.py", line 228, in _make_base_candidate_from_link
2026-05-16 00:27:52.022255 : DEBUG_ARR:     self._link_candidate_cache[link] = LinkCandidate(
2026-05-16 00:27:52.022258 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/candidates.py", line 290, in __init__
2026-05-16 00:27:52.022261 : DEBUG_ARR:     super().__init__(
2026-05-16 00:27:52.022264 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/candidates.py", line 156, in __init__
2026-05-16 00:27:52.022267 : DEBUG_ARR:     self.dist = self._prepare()
2026-05-16 00:27:52.022270 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/candidates.py", line 222, in _prepare
2026-05-16 00:27:52.022273 : DEBUG_ARR:     dist = self._prepare_distribution()
2026-05-16 00:27:52.022276 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/resolution/resolvelib/candidates.py", line 301, in _prepare_distribution
2026-05-16 00:27:52.022279 : DEBUG_ARR:     return preparer.prepare_linked_requirement(self._ireq, parallel_builds=True)
2026-05-16 00:27:52.022282 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/operations/prepare.py", line 525, in prepare_linked_requirement
2026-05-16 00:27:52.022285 : DEBUG_ARR:     return self._prepare_linked_requirement(req, parallel_builds)
2026-05-16 00:27:52.022288 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/operations/prepare.py", line 596, in _prepare_linked_requirement
2026-05-16 00:27:52.022291 : DEBUG_ARR:     local_file = unpack_url(
2026-05-16 00:27:52.022294 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/operations/prepare.py", line 168, in unpack_url
2026-05-16 00:27:52.022297 : DEBUG_ARR:     file = get_http_url(
2026-05-16 00:27:52.022300 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/operations/prepare.py", line 109, in get_http_url
2026-05-16 00:27:52.022303 : DEBUG_ARR:     from_path, content_type = download(link, temp_dir.path)
2026-05-16 00:27:52.022306 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/network/download.py", line 147, in __call__
2026-05-16 00:27:52.022309 : DEBUG_ARR:     for chunk in chunks:
2026-05-16 00:27:52.022313 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/cli/progress_bars.py", line 53, in _rich_progress_bar
2026-05-16 00:27:52.022316 : DEBUG_ARR:     for chunk in iterable:
2026-05-16 00:27:52.022319 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_internal/network/utils.py", line 63, in response_chunks
2026-05-16 00:27:52.022339 : DEBUG_ARR:     for chunk in response.raw.stream(
2026-05-16 00:27:52.022343 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/urllib3/response.py", line 622, in stream
2026-05-16 00:27:52.022346 : DEBUG_ARR:     data = self.read(amt=amt, decode_content=decode_content)
2026-05-16 00:27:52.022349 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/urllib3/response.py", line 587, in read
2026-05-16 00:27:52.022352 : DEBUG_ARR:     raise IncompleteRead(self._fp_bytes_read, self.length_remaining)
2026-05-16 00:27:52.022355 : DEBUG_ARR:   File "/usr/lib/python3.8/contextlib.py", line 131, in __exit__
2026-05-16 00:27:52.022358 : DEBUG_ARR:     self.gen.throw(type, value, traceback)
2026-05-16 00:27:52.022361 : DEBUG_ARR:   File "/home/ubuntu/env-python3/lib/python3.8/site-packages/pip/_vendor/urllib3/response.py", line 443, in _error_catcher
2026-05-16 00:27:52.022364 : DEBUG_ARR:     raise ReadTimeoutError(self._pool, None, "Read timed out.")
2026-05-16 00:27:52.022367 : DEBUG_ARR: pip._vendor.urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='mirrors.aliyun.com', port=443): Read timed out.
2026-05-16 00:27:52.022370 : DEBUG_ARR: [0m[91m
2026-05-16 00:27:52.022373 : DEBUG_ARR: [notice] A new release of pip is available: 24.0 -> 25.0.1
2026-05-16 00:27:52.022376 : DEBUG_ARR: [notice] To update, run: python3 -m pip install --upgrade pip
2026-05-16 00:27:52.022381 : DEBUG_ARR: [0mThe command '/bin/sh -c if ! pip3 list | grep -c pytest >/dev/null && [ 'ubuntu' != 'AzDevOps' ] && [ -d /var/AzDevOps/env-python3 ]; then /bin/bash -c 'python3 -m venv ${HOME}/env-python3'; /bin/bash -c "${HOME}/env-python3/bin/pip install  -i https://mirrors.aliyun.com/pypi/simple/ --upgrade 'pip<24.1'"; /bin/bash -c '${HOME}/env-python3/bin/pip install  -i https://mirrors.aliyun.com/pypi/simple/ wheel'; /bin/bash -c '${HOME}/env-python3/bin/pip  install  -i https://mirrors.aliyun.com/pypi/simple/ --upgrade paramiko'; /bin/bash -c '${HOME}/env-python3/bin/pip install  -i https://mirrors.aliyun.com/pypi/simple/ $(/var/AzDevOps/env-python3/bin/pip freeze | grep -vE "distro|PyGObject|python-apt|unattended-upgrades|dbus-python")'; fi' returned a non-zero code: 2
2026-05-16 00:27:52.022385 : DEBUG_ARR: ERROR: failed to build docker image: docker-sonic-mgmt-ubuntu:master
2026-05-16 00:27:52.022388 : DEBUG_ARR: INFO: cleanup a temporary dir: /tmp/tmp.Shux9ua2Ad
2026-05-16 00:27:52.022391 : DEBUG_ARR: INFO: creating a container: sonic-mgmt-test ...
2026-05-16 00:27:52.022394 : DEBUG_ARR: 8e5ae2d928ccbe3eeae2a62410a5a3f85b78d0b331f24f7fd4fc429d6e8da744
2026-05-16 00:27:52.022397 : DEBUG_ARR:  * Restarting OpenBSD Secure Shell server sshd
2026-05-16 00:27:52.022400 : DEBUG_ARR:    ...done.
2026-05-16 00:27:52.022403 : DEBUG_ARR: INFO: verifying UID and GID in container matches host
2026-05-16 00:27:52.022406 : DEBUG_ARR: ******************************************************************************
2026-05-16 00:27:52.022409 : DEBUG_ARR: EXEC: docker exec --user ubuntu -ti sonic-mgmt-test bash
2026-05-16 00:27:52.022412 : DEBUG_ARR: SSH:  ssh -i ~/.ssh/id_rsa_docker_sonic_mgmt ubuntu@172.17.0.2
2026-05-16 00:27:52.022415 : DEBUG_ARR: ******************************************************************************
2026-05-16 00:27:52.022418 : DEBUG_ARR: 
2026-05-16 00:27:52.022421 : DEBUG_ARR: INFO: sonic-mgmt configuration is done!
2026-05-16 00:27:52.022424 : DEBUG_ARR: 
2026-05-16 00:27:52.022453 : Sleep 10 second
2026-05-16 00:28:02.032839 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "docker exec --user ubuntu  sonic-mgmt-test bash -c 'cd /usr/share/sonic/device; sudo cp /data/g200dev.tar .; sudo tar xvf g200dev.tar'; ls -l *g200*"
2026-05-16 00:28:02.898848 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/
2026-05-16 00:28:02.898890 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/minigraph.xml
2026-05-16 00:28:02.898895 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/platform_asic
2026-05-16 00:28:02.898898 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/g200/
2026-05-16 00:28:02.898901 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/g200/acl_key_profile.json
2026-05-16 00:28:02.898904 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/g200/sai_init_config.json
2026-05-16 00:28:02.898908 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/g200/sai_sdk_log_config.json
2026-05-16 00:28:02.898912 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/g200/port_config.ini
2026-05-16 00:28:02.898915 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/g200/sai.profile
2026-05-16 00:28:02.898918 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/g200/nsim_config.json
2026-05-16 00:28:02.898921 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/plugins/
2026-05-16 00:28:02.898924 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/plugins/eeprom.py
2026-05-16 00:28:02.898928 : DEBUG_ARR: x86_64-kvm-g200_x86_64-r0/default_sku
2026-05-16 00:28:02.898931 : DEBUG_ARR: -rw-r--r-- 1 root root 30720 May 16 07:20 g200dev.tar
2026-05-16 00:28:02.898973 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "docker exec --user ubuntu  sonic-mgmt-test bash -c 'cd /usr/share/sonic/device; sudo cp -r x86_64-kvm-g200_x86_64-r0/g200 x86_64-kvm_x86_64-r0;ls -l x86_64-kvm_x86_64-r0/g200'"
2026-05-16 00:28:03.595545 : DEBUG_ARR: total 32
2026-05-16 00:28:03.595588 : DEBUG_ARR: -rw-r--r-- 1 root root 8704 May 16 07:28 acl_key_profile.json
2026-05-16 00:28:03.595593 : DEBUG_ARR: -rw-r--r-- 1 root root  924 May 16 07:28 nsim_config.json
2026-05-16 00:28:03.595596 : DEBUG_ARR: -rw-r--r-- 1 root root 2111 May 16 07:28 port_config.ini
2026-05-16 00:28:03.595600 : DEBUG_ARR: -rw-r--r-- 1 root root  201 May 16 07:28 sai.profile
2026-05-16 00:28:03.595603 : DEBUG_ARR: -rw-r--r-- 1 root root  780 May 16 07:28 sai_init_config.json
2026-05-16 00:28:03.595606 : DEBUG_ARR: -rw-r--r-- 1 root root 3482 May 16 07:28 sai_sdk_log_config.json
2026-05-16 00:28:03.595651 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "docker exec --user ubuntu  sonic-mgmt-test bash -c 'cd /usr/share/sonic/device; sudo cp /data/q200dev.tar .; sudo tar xvf q200dev.tar'; ls -l *q200*"
2026-05-16 00:28:04.307821 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/
2026-05-16 00:28:04.307879 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/default_sku
2026-05-16 00:28:04.307889 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/q200/
2026-05-16 00:28:04.307896 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/q200/q200-128x100G-vs.json
2026-05-16 00:28:04.307902 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/q200/port_config.ini
2026-05-16 00:28:04.307908 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/q200/sai.profile
2026-05-16 00:28:04.307914 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/q200/buffer_ports_t0.j2
2026-05-16 00:28:04.307920 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/q200/buffers_defaults_t0.j2
2026-05-16 00:28:04.307926 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/q200/buffers.json.j2
2026-05-16 00:28:04.307931 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/minigraph.xml
2026-05-16 00:28:04.307937 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/plugins/
2026-05-16 00:28:04.307944 : DEBUG_ARR: x86_64-kvm-q200_x86_64-r0/plugins/eeprom.py
2026-05-16 00:28:04.307950 : DEBUG_ARR: -rw-r--r-- 1 root root 40960 May 16 07:20 q200dev.tar
2026-05-16 00:28:04.308007 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "docker exec --user ubuntu  sonic-mgmt-test bash -c 'cd /usr/share/sonic/device; sudo cp -r x86_64-kvm-q200_x86_64-r0/q200 x86_64-kvm_x86_64-r0;ls -l x86_64-kvm_x86_64-r0/q200'"
2026-05-16 00:28:05.022867 : DEBUG_ARR: total 44
2026-05-16 00:28:05.022908 : DEBUG_ARR: -rw-r--r-- 1 root root   223 May 16 07:28 buffer_ports_t0.j2
2026-05-16 00:28:05.022913 : DEBUG_ARR: -rw-r--r-- 1 root root    67 May 16 07:28 buffers.json.j2
2026-05-16 00:28:05.022917 : DEBUG_ARR: -rw-r--r-- 1 root root  1034 May 16 07:28 buffers_defaults_t0.j2
2026-05-16 00:28:05.022920 : DEBUG_ARR: -rw-r--r-- 1 root root  9695 May 16 07:28 port_config.ini
2026-05-16 00:28:05.022994 : DEBUG_ARR: -rw-r--r-- 1 root root 13694 May 16 07:28 q200-128x100G-vs.json
2026-05-16 00:28:05.022999 : DEBUG_ARR: -rw-r--r-- 1 root root   141 May 16 07:28 sai.profile
2026-05-16 00:28:05.023052 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "docker exec --user ubuntu  sonic-mgmt-test bash -c 'cd /usr/share/sonic/device; sudo cp /data/p200dev.tar .; sudo tar xvf p200dev.tar'; ls -l *p200*"
2026-05-16 00:28:05.732528 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/
2026-05-16 00:28:05.732570 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/minigraph.xml
2026-05-16 00:28:05.732576 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/default_sku
2026-05-16 00:28:05.732581 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/cisco_asic
2026-05-16 00:28:05.732585 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/plugins/
2026-05-16 00:28:05.732588 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/plugins/eeprom.py
2026-05-16 00:28:05.732591 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/p200/
2026-05-16 00:28:05.732595 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/p200/sai_sdk_log_config.json
2026-05-16 00:28:05.732598 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/p200/buffers_defaults_t0.j2
2026-05-16 00:28:05.732601 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/p200/sai.profile
2026-05-16 00:28:05.732605 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/p200/traps.json
2026-05-16 00:28:05.732608 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/p200/sai_init_config.json
2026-05-16 00:28:05.732611 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/p200/buffers.json.j2
2026-05-16 00:28:05.732614 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/p200/port_config.ini
2026-05-16 00:28:05.732617 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/p200/buffer_ports_t0.j2
2026-05-16 00:28:05.732621 : DEBUG_ARR: x86_64-kvm-p200_x86_64-r0/platform_asic
2026-05-16 00:28:05.732624 : DEBUG_ARR: -rw-r--r-- 1 root root 40960 May 16 07:20 p200dev.tar
2026-05-16 00:28:05.732664 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "docker exec --user ubuntu  sonic-mgmt-test bash -c 'cd /usr/share/sonic/device; sudo cp -r x86_64-kvm-p200_x86_64-r0/p200 x86_64-kvm_x86_64-r0;ls -l x86_64-kvm_x86_64-r0/p200'"
2026-05-16 00:28:06.430139 : DEBUG_ARR: total 44
2026-05-16 00:28:06.430182 : DEBUG_ARR: -rw-r--r-- 1 root root  223 May 16 07:28 buffer_ports_t0.j2
2026-05-16 00:28:06.430187 : DEBUG_ARR: -rw-r--r-- 1 root root   67 May 16 07:28 buffers.json.j2
2026-05-16 00:28:06.430191 : DEBUG_ARR: -rw-r--r-- 1 root root 1034 May 16 07:28 buffers_defaults_t0.j2
2026-05-16 00:28:06.430194 : DEBUG_ARR: -rw-r--r-- 1 root root 8350 May 16 07:28 port_config.ini
2026-05-16 00:28:06.430197 : DEBUG_ARR: -rw-r--r-- 1 root root  212 May 16 07:28 sai.profile
2026-05-16 00:28:06.430200 : DEBUG_ARR: -rw-r--r-- 1 root root 2071 May 16 07:28 sai_init_config.json
2026-05-16 00:28:06.430204 : DEBUG_ARR: -rw-r--r-- 1 root root 3501 May 16 07:28 sai_sdk_log_config.json
2026-05-16 00:28:06.430207 : DEBUG_ARR: -rw-r--r-- 1 root root 4419 May 16 07:28 traps.json
2026-05-16 00:28:06.430248 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "docker exec --user ubuntu  sonic-mgmt-test bash -c 'cd /usr/share/sonic/device/x86_64-kvm_x86_64-r0/; sudo cp /data/cisco-8101-p4-32x100-vs.tar .; sudo tar xvf cisco-8101-p4-32x100-vs.tar'"
2026-05-16 00:28:07.139716 : DEBUG_ARR: cisco-8101-p4-32x100-vs/
2026-05-16 00:28:07.139761 : DEBUG_ARR: cisco-8101-p4-32x100-vs/acl_key_profile.json
2026-05-16 00:28:07.139766 : DEBUG_ARR: cisco-8101-p4-32x100-vs/pg_profile_lookup.ini
2026-05-16 00:28:07.139769 : DEBUG_ARR: cisco-8101-p4-32x100-vs/ciscovs_sai.profile
2026-05-16 00:28:07.139773 : DEBUG_ARR: cisco-8101-p4-32x100-vs/buffers.json.j2
2026-05-16 00:28:07.139776 : DEBUG_ARR: cisco-8101-p4-32x100-vs/sai_init_config.json
2026-05-16 00:28:07.139782 : DEBUG_ARR: cisco-8101-p4-32x100-vs/lanemap.ini
2026-05-16 00:28:07.139785 : DEBUG_ARR: cisco-8101-p4-32x100-vs/sai.profile
2026-05-16 00:28:07.139788 : DEBUG_ARR: cisco-8101-p4-32x100-vs/buffers_defaults_t1.j2
2026-05-16 00:28:07.139791 : DEBUG_ARR: cisco-8101-p4-32x100-vs/buffers_defaults_t0.j2
2026-05-16 00:28:07.139794 : DEBUG_ARR: cisco-8101-p4-32x100-vs/qos.json.j2
2026-05-16 00:28:07.139797 : DEBUG_ARR: cisco-8101-p4-32x100-vs/sai_sdk_log_config.json
2026-05-16 00:28:07.139800 : DEBUG_ARR: cisco-8101-p4-32x100-vs/port_config.ini
2026-05-16 00:28:07.139803 : DEBUG_ARR: cisco-8101-p4-32x100-vs/pai.profile
2026-05-16 00:28:07.139807 : DEBUG_ARR: cisco-8101-p4-32x100-vs/nsim_config.json
2026-05-16 00:28:07.139810 : DEBUG_ARR: cisco-8101-p4-32x100-vs/sai_mlnx.profile
2026-05-16 00:28:07.140124 : Current directory /home/super/workspace/PhoenixWingDailySRv6Test/na_lab/pytest_env
{'conf-name': 'vms-kvm-t0', 'group-name': 'vms6-1', 'topo': 't0', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-t0-64', 'group-name': 'vms6-1', 'topo': 't0-64', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-02'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-t0-64-32', 'group-name': 'vms6-1', 'topo': 't0-64-32', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-02'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-t1-lag', 'group-name': 'vms6-2', 'topo': 't1-lag', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-02', 'ptf_ip': '10.250.0.106/24', 'ptf_ipv6': 'fec0::ffff:afa:6/64', 'server': 'server_1', 'vm_base': 'VM0104', 'dut': ['vlab-03'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-t0-2', 'group-name': 'vms6-3', 'topo': 't0', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-03', 'ptf_ip': '10.250.0.108/24', 'ptf_ipv6': 'fec0::ffff:afa:8/64', 'server': 'server_1', 'vm_base': 'VM0104', 'dut': ['vlab-04'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-dual-t0', 'group-name': 'vms6-4', 'topo': 'dualtor', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-04', 'ptf_ip': '10.250.0.109/24', 'ptf_ipv6': 'fec0::ffff:afa:9/64', 'server': 'server_1', 'vm_base': 'VM0108', 'dut': ['vlab-05', 'vlab-06'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Dual-TOR testbed'}
{'conf-name': 'vms-kvm-multi-asic-t1-lag', 'group-name': 'vms6-4', 'topo': 't1-64-lag', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-05', 'ptf_ip': '10.250.0.110/24', 'ptf_ipv6': 'fec0::ffff:afa:a/64', 'server': 'server_1', 'vm_base': 'VM0104', 'dut': ['vlab-07'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests multi-asic virtual switch vm'}
{'conf-name': 'vms-kvm-four-asic-t1-lag', 'group-name': 'vms6-4', 'topo': 't1-8-lag', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-05', 'ptf_ip': '10.250.0.110/24', 'ptf_ipv6': 'fec0::ffff:afa:a/64', 'server': 'server_1', 'vm_base': 'VM0128', 'dut': ['vlab-08'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests multi-asic virtual switch vm'}
{'conf-name': 'vms-kvm-t2', 'group-name': 'vms6-4', 'topo': 't2-vs', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-04', 'ptf_ip': '10.250.0.109/24', 'ptf_ipv6': 'fec0::ffff:afa:9/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-t2-01', 'vlab-t2-02', 'vlab-t2-sup'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'T2 Virtual chassis'}
reading
found testbed vms-kvm-ciscovs-7nodes
Starting VMs for testbed 'vms-kvm-ciscovs-7nodes' on server 'server_1'

PLAY [servers:&vm_host] ********************************************************

TASK [vm_set : Pick package_installation from env] *****************************
Saturday 16 May 2026  07:28:09 +0000 (0:00:00.157)       0:00:00.157 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Set the default variable package_installation] ******************
Saturday 16 May 2026  07:28:09 +0000 (0:00:00.031)       0:00:00.189 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : get host distribution] ******************************************
Saturday 16 May 2026  07:28:09 +0000 (0:00:00.028)       0:00:00.217 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : get host distribution version] **********************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:01.195)       0:00:01.413 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : get host kernel version] ****************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.205)       0:00:01.618 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Check if kernel upgrade needed] *********************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.212)       0:00:01.830 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : debug] **********************************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.031)       0:00:01.862 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Upgrade kernel package] *****************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.027)       0:00:01.889 ********** 
skipping: [STR-ACS-VSERV-01] => (item=[]) 

TASK [vm_set : Prompt for rebooting] *******************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.041)       0:00:01.930 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Install necessary packages] *************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.027)       0:00:01.958 ********** 
skipping: [STR-ACS-VSERV-01] => (item=[]) 

TASK [vm_set : Install necessary packages] *************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.050)       0:00:02.008 ********** 
skipping: [STR-ACS-VSERV-01] => (item=[]) 

TASK [vm_set : Install necessary packages] *************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.053)       0:00:02.062 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Install necessary packages] *************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.026)       0:00:02.088 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Get default pip_executable] *************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.027)       0:00:02.116 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Get default pip_executable] *************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.029)       0:00:02.145 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : remove old python packages] *************************************
Saturday 16 May 2026  07:28:11 +0000 (0:00:00.032)       0:00:02.178 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : include_tasks] **************************************************
Saturday 16 May 2026  07:28:13 +0000 (0:00:01.769)       0:00:03.948 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Ensure ubuntu in docker,sudo group] *****************************
Saturday 16 May 2026  07:28:13 +0000 (0:00:00.030)       0:00:03.978 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Ensure ubuntu in libvirt group] *********************************
Saturday 16 May 2026  07:28:14 +0000 (0:00:00.519)       0:00:04.497 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Install br_netfilter kernel module] *****************************
Saturday 16 May 2026  07:28:14 +0000 (0:00:00.246)       0:00:04.744 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Set sysctl bridge parameters for testbed] ***********************
Saturday 16 May 2026  07:28:14 +0000 (0:00:00.409)       0:00:05.154 ********** 
changed: [STR-ACS-VSERV-01] => (item=net.bridge.bridge-nf-call-arptables)
ok: [STR-ACS-VSERV-01] => (item=net.bridge.bridge-nf-call-ip6tables)
ok: [STR-ACS-VSERV-01] => (item=net.bridge.bridge-nf-call-iptables)

TASK [vm_set : Set sysctl RCVBUF max parameter for testbed] ********************
Saturday 16 May 2026  07:28:16 +0000 (0:00:01.816)       0:00:06.970 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Set sysctl RCVBUF default parameter for testbed] ****************
Saturday 16 May 2026  07:28:16 +0000 (0:00:00.205)       0:00:07.176 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Increase IPv6 route cache size] *********************************
Saturday 16 May 2026  07:28:17 +0000 (0:00:00.207)       0:00:07.383 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Setup external front port] **************************************
Saturday 16 May 2026  07:28:17 +0000 (0:00:00.482)       0:00:07.866 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Setup internal management network] ******************************
Saturday 16 May 2026  07:28:17 +0000 (0:00:00.028)       0:00:07.894 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : getent] *********************************************************
Saturday 16 May 2026  07:28:17 +0000 (0:00:00.027)       0:00:07.922 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:18 +0000 (0:00:00.413)       0:00:08.335 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:18 +0000 (0:00:00.034)       0:00:08.369 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : debug] **********************************************************
Saturday 16 May 2026  07:28:18 +0000 (0:00:00.035)       0:00:08.405 ********** 
ok: [STR-ACS-VSERV-01] => {
    "msg": "home_path = /home/ubuntu root_path = /home/ubuntu/veos-vm"
}

TASK [vm_set : Require veos or SONiC or cisco VMs by default] ******************
Saturday 16 May 2026  07:28:18 +0000 (0:00:00.029)       0:00:08.435 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : veos or SONiC or cisco VMs not needed when setting up Kubernetes master] ***
Saturday 16 May 2026  07:28:18 +0000 (0:00:00.026)       0:00:08.461 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : VMs not needed in case of Keysight API Server] ******************
Saturday 16 May 2026  07:28:18 +0000 (0:00:00.027)       0:00:08.489 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : VMs not needed in case of Keysight IxANVL] **********************
Saturday 16 May 2026  07:28:18 +0000 (0:00:00.027)       0:00:08.516 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Retrieve a list of the defined VMs] *****************************
Saturday 16 May 2026  07:28:18 +0000 (0:00:00.026)       0:00:08.543 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Retrieve a list of the running VMs] *****************************
Saturday 16 May 2026  07:28:18 +0000 (0:00:00.693)       0:00:09.237 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Set vm_state_string according to ansible version] ***************
Saturday 16 May 2026  07:28:19 +0000 (0:00:00.233)       0:00:09.470 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Print ansible version and vm_state_string] **********************
Saturday 16 May 2026  07:28:19 +0000 (0:00:00.031)       0:00:09.501 ********** 
ok: [STR-ACS-VSERV-01] => {
    "msg": "ansible version is 2.8.12 and vm_state_string is pause"
}

TASK [vm_set : Retrieve a list of the paused VMs with status=pause] ************
Saturday 16 May 2026  07:28:19 +0000 (0:00:00.032)       0:00:09.534 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Require VMs as CEOS by default] *********************************
Saturday 16 May 2026  07:28:19 +0000 (0:00:00.233)       0:00:09.767 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check VM type] **************************************************
Saturday 16 May 2026  07:28:19 +0000 (0:00:00.027)       0:00:09.795 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Ensure /home/ubuntu/veos-vm exists] *****************************
Saturday 16 May 2026  07:28:19 +0000 (0:00:00.029)       0:00:09.825 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Install cleanup script] *****************************************
Saturday 16 May 2026  07:28:20 +0000 (0:00:00.496)       0:00:10.322 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Copy vm_resumer.py to the /home/ubuntu/veos-vm] *****************
Saturday 16 May 2026  07:28:21 +0000 (0:00:01.136)       0:00:11.458 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Find current server group] **************************************
Saturday 16 May 2026  07:28:21 +0000 (0:00:00.675)       0:00:12.134 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Extract VM names from the inventory] ****************************
Saturday 16 May 2026  07:28:21 +0000 (0:00:00.035)       0:00:12.169 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Limit VM] *******************************************************
Saturday 16 May 2026  07:28:21 +0000 (0:00:00.036)       0:00:12.205 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Generate vm list of target VMs] *********************************
Saturday 16 May 2026  07:28:21 +0000 (0:00:00.033)       0:00:12.238 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set fallback default value for VM_targets] **********************
Saturday 16 May 2026  07:28:21 +0000 (0:00:00.031)       0:00:12.270 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Set vm configuration properties when configuration is defined] ***
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.036)       0:00:12.306 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set vm configuration properties when configuration is not defined] ***
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.032)       0:00:12.339 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Stop VMs] *******************************************************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.034)       0:00:12.374 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start VMs] ******************************************************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.032)       0:00:12.406 ********** 
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/start.yml for STR-ACS-VSERV-01

TASK [vm_set : Require VMs as CEOS by default] *********************************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.119)       0:00:12.526 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Load topo variables] ********************************************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.032)       0:00:12.558 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Pick provided max num of fp] ************************************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.137)       0:00:12.696 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : debug] **********************************************************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.037)       0:00:12.733 ********** 
ok: [STR-ACS-VSERV-01] => {
    "msg": "max_fp_num 6"
}

TASK [vm_set : Filter VMs for specified topology] ******************************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.037)       0:00:12.771 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Create directory for vm images and vm disks] ********************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.041)       0:00:12.812 ********** 
ok: [STR-ACS-VSERV-01] => (item=/home/ubuntu/veos-vm/images)
ok: [STR-ACS-VSERV-01] => (item=/home/ubuntu/veos-vm/disks)

TASK [vm_set : Check hdd image] ************************************************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.396)       0:00:13.208 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Fail if skip_veos_image_downloading is true] ********************
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.033)       0:00:13.242 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init veos_hdd_image_urls when veos_hdd_image_url value type is string] ***
Saturday 16 May 2026  07:28:22 +0000 (0:00:00.033)       0:00:13.276 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init veos_hdd_image_urls when veos_hdd_image_url value type is list] ***
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.308 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init working_image_urls list] ***********************************
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.341 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Loop veos_hdd_image_urls to find out working URLs] **************
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.031)       0:00:13.373 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Fail if no working veos hdd image download url is found] ********
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.034)       0:00:13.407 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Download veos hdd image from the first URL in working_image_urls] ***
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.440 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check cd image] *************************************************
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.472 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Fail if skip_veos_image_downloading is true] ********************
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.036)       0:00:13.509 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init veos_cd_image_urls when veos_cd_image_url value type is string] ***
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.541 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init veos_cd_image_urls when veos_cd_image_url value type is list] ***
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.574 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init working_image_urls list] ***********************************
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.607 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Loop veos_cd_image_urls to find out working URLs] ***************
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.640 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Fail if no working veos cd image download url is found] *********
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.035)       0:00:13.675 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Download veos cd image from the first URL in working_image_urls] ***
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.708 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.740 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check SONiC image] **********************************************
Saturday 16 May 2026  07:28:23 +0000 (0:00:00.032)       0:00:13.773 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Fail if skip_vsonic_image_downloading is true] ******************
Saturday 16 May 2026  07:28:29 +0000 (0:00:06.199)       0:00:19.972 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init vsonic_image_urls when vsonic_image_url value type is string] ***
Saturday 16 May 2026  07:28:29 +0000 (0:00:00.037)       0:00:20.010 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init vsonic_image_urls when vsonic_image_url value type is list] ***
Saturday 16 May 2026  07:28:29 +0000 (0:00:00.035)       0:00:20.046 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init working_image_urls list] ***********************************
Saturday 16 May 2026  07:28:29 +0000 (0:00:00.036)       0:00:20.082 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Loop vsonic_image_urls to find out working URLs] ****************
Saturday 16 May 2026  07:28:29 +0000 (0:00:00.035)       0:00:20.118 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Fail if no working SONiC image download url is found] ***********
Saturday 16 May 2026  07:28:29 +0000 (0:00:00.037)       0:00:20.155 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Download SONiC image from the first URL in working_image_urls] ***
Saturday 16 May 2026  07:28:29 +0000 (0:00:00.035)       0:00:20.191 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Get downloaded SONiC image info] ********************************
Saturday 16 May 2026  07:28:29 +0000 (0:00:00.036)       0:00:20.227 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Get downloaded SONiC image info] ********************************
Saturday 16 May 2026  07:28:29 +0000 (0:00:00.035)       0:00:20.263 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Rename file to have a .gz suffix] *******************************
Saturday 16 May 2026  07:28:36 +0000 (0:00:06.373)       0:00:26.636 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Decompress file] ************************************************
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.037)       0:00:26.673 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.037)       0:00:26.711 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Check cisco image] **********************************************
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.037)       0:00:26.748 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Fail if skip_vcisco_image_downloading is true] ******************
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.032)       0:00:26.780 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init vcisco_image_urls when vcisco_image_url value type is string] ***
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.033)       0:00:26.814 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init vcisco_image_urls when vcisco_image_url value type is list] ***
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.033)       0:00:26.848 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Init working_image_urls list] ***********************************
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.033)       0:00:26.881 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Loop vcisco_image_urls to find out working URLs] ****************
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.032)       0:00:26.913 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Fail if no working cisco image download url is found] ***********
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.035)       0:00:26.949 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Download cisco image from the first URL in working_image_urls] ***
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.032)       0:00:26.981 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.032)       0:00:27.013 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Create VMs network] *********************************************
Saturday 16 May 2026  07:28:36 +0000 (0:00:00.032)       0:00:27.046 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Default autostart to no when it is not defined] *****************
Saturday 16 May 2026  07:28:45 +0000 (0:00:09.003)       0:00:36.049 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Default batch_size to 1 when it is not defined] *****************
Saturday 16 May 2026  07:28:45 +0000 (0:00:00.038)       0:00:36.088 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Default wait interval to 0 if it is not defined] ****************
Saturday 16 May 2026  07:28:45 +0000 (0:00:00.039)       0:00:36.128 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Start VMs] ******************************************************
Saturday 16 May 2026  07:28:45 +0000 (0:00:00.039)       0:00:36.167 ********** 
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/start_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/start_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/start_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/start_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/start_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/start_vm.yml for STR-ACS-VSERV-01

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.190)       0:00:36.358 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.043)       0:00:36.402 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.039)       0:00:36.441 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.032)       0:00:36.474 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.034)       0:00:36.508 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.038)       0:00:36.547 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Find current server group] **************************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.034)       0:00:36.582 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Extract VM names from the inventory] ****************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.035)       0:00:36.617 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Generate hostname for target VM] ********************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.038)       0:00:36.656 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.043)       0:00:36.699 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Device debug output] ********************************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.040)       0:00:36.739 ********** 
ok: [STR-ACS-VSERV-01] => {
    "msg": "hostname = VM0100 host internal name = PE1 sonic_password = password vm_type = vsonic serial port = 7000 ip = 10.250.0.51 hwsku = cisco-8101-p4-32x100-vs"
}

TASK [vm_set : Check destination file existance] *******************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.050)       0:00:36.789 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Copy vsonic disk image for VM0100] ******************************
Saturday 16 May 2026  07:28:46 +0000 (0:00:00.212)       0:00:37.002 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Define vm VM0100, hwsku cisco-8101-p4-32x100-vs] ****************
Saturday 16 May 2026  07:29:27 +0000 (0:00:40.998)       0:01:18.000 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0100 if it requires fix] ***************************
Saturday 16 May 2026  07:29:31 +0000 (0:00:03.926)       0:01:21.927 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm VM0100] ************************************************
Saturday 16 May 2026  07:29:31 +0000 (0:00:00.038)       0:01:21.966 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Find out VM index] **********************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:03.480)       0:01:25.446 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Pause after started every 6 VMs] ********************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.044)       0:01:25.491 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.033)       0:01:25.524 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.032)       0:01:25.556 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.041)       0:01:25.598 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.034)       0:01:25.633 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.038)       0:01:25.671 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.037)       0:01:25.708 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Find current server group] **************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.035)       0:01:25.744 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Extract VM names from the inventory] ****************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.037)       0:01:25.781 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Generate hostname for target VM] ********************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.040)       0:01:25.822 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.046)       0:01:25.869 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Device debug output] ********************************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.042)       0:01:25.911 ********** 
ok: [STR-ACS-VSERV-01] => {
    "msg": "hostname = VM0101 host internal name = PE2 sonic_password = password vm_type = vsonic serial port = 7001 ip = 10.250.0.52 hwsku = cisco-8101-p4-32x100-vs"
}

TASK [vm_set : Check destination file existance] *******************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.046)       0:01:25.958 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Copy vsonic disk image for VM0101] ******************************
Saturday 16 May 2026  07:29:35 +0000 (0:00:00.213)       0:01:26.172 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Define vm VM0101, hwsku cisco-8101-p4-32x100-vs] ****************
Saturday 16 May 2026  07:30:19 +0000 (0:00:43.447)       0:02:09.619 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0101 if it requires fix] ***************************
Saturday 16 May 2026  07:30:21 +0000 (0:00:01.927)       0:02:11.547 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm VM0101] ************************************************
Saturday 16 May 2026  07:30:21 +0000 (0:00:00.039)       0:02:11.586 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Find out VM index] **********************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:04.996)       0:02:16.583 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Pause after started every 6 VMs] ********************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.040)       0:02:16.624 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.034)       0:02:16.658 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.034)       0:02:16.693 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.043)       0:02:16.736 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.034)       0:02:16.770 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.037)       0:02:16.807 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.033)       0:02:16.841 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Find current server group] **************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.037)       0:02:16.879 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Extract VM names from the inventory] ****************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.038)       0:02:16.917 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Generate hostname for target VM] ********************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.040)       0:02:16.957 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.044)       0:02:17.002 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Device debug output] ********************************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.042)       0:02:17.044 ********** 
ok: [STR-ACS-VSERV-01] => {
    "msg": "hostname = VM0102 host internal name = PE3 sonic_password = password vm_type = vsonic serial port = 7002 ip = 10.250.0.53 hwsku = cisco-8101-p4-32x100-vs"
}

TASK [vm_set : Check destination file existance] *******************************
Saturday 16 May 2026  07:30:26 +0000 (0:00:00.048)       0:02:17.092 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Copy vsonic disk image for VM0102] ******************************
Saturday 16 May 2026  07:30:27 +0000 (0:00:00.209)       0:02:17.302 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Define vm VM0102, hwsku cisco-8101-p4-32x100-vs] ****************
Saturday 16 May 2026  07:31:25 +0000 (0:00:58.197)       0:03:15.499 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0102 if it requires fix] ***************************
Saturday 16 May 2026  07:31:28 +0000 (0:00:03.565)       0:03:19.065 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm VM0102] ************************************************
Saturday 16 May 2026  07:31:28 +0000 (0:00:00.037)       0:03:19.103 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Find out VM index] **********************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:05.369)       0:03:24.472 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Pause after started every 6 VMs] ********************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.042)       0:03:24.515 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.034)       0:03:24.549 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.035)       0:03:24.585 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.043)       0:03:24.628 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.035)       0:03:24.664 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.038)       0:03:24.702 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.037)       0:03:24.740 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Find current server group] **************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.036)       0:03:24.777 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Extract VM names from the inventory] ****************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.037)       0:03:24.814 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Generate hostname for target VM] ********************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.041)       0:03:24.856 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.047)       0:03:24.904 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Device debug output] ********************************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.044)       0:03:24.948 ********** 
ok: [STR-ACS-VSERV-01] => {
    "msg": "hostname = VM0103 host internal name = P3 sonic_password = password vm_type = vsonic serial port = 7003 ip = 10.250.0.54 hwsku = cisco-8101-p4-32x100-vs"
}

TASK [vm_set : Check destination file existance] *******************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.048)       0:03:24.996 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Copy vsonic disk image for VM0103] ******************************
Saturday 16 May 2026  07:31:34 +0000 (0:00:00.256)       0:03:25.252 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Define vm VM0103, hwsku cisco-8101-p4-32x100-vs] ****************
Saturday 16 May 2026  07:32:33 +0000 (0:00:58.147)       0:04:23.400 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0103 if it requires fix] ***************************
Saturday 16 May 2026  07:32:33 +0000 (0:00:00.764)       0:04:24.165 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm VM0103] ************************************************
Saturday 16 May 2026  07:32:33 +0000 (0:00:00.041)       0:04:24.207 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Find out VM index] **********************************************
Saturday 16 May 2026  07:32:37 +0000 (0:00:03.903)       0:04:28.110 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Pause after started every 6 VMs] ********************************
Saturday 16 May 2026  07:32:37 +0000 (0:00:00.056)       0:04:28.167 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:32:37 +0000 (0:00:00.039)       0:04:28.207 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:32:37 +0000 (0:00:00.039)       0:04:28.246 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.072)       0:04:28.319 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.051)       0:04:28.371 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.042)       0:04:28.414 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.062)       0:04:28.476 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Find current server group] **************************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.042)       0:04:28.519 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Extract VM names from the inventory] ****************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.044)       0:04:28.563 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Generate hostname for target VM] ********************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.047)       0:04:28.611 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.063)       0:04:28.674 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Device debug output] ********************************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.072)       0:04:28.747 ********** 
ok: [STR-ACS-VSERV-01] => {
    "msg": "hostname = VM0104 host internal name = P2 sonic_password = password vm_type = vsonic serial port = 7004 ip = 10.250.0.55 hwsku = cisco-8101-p4-32x100-vs"
}

TASK [vm_set : Check destination file existance] *******************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.055)       0:04:28.803 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Copy vsonic disk image for VM0104] ******************************
Saturday 16 May 2026  07:32:38 +0000 (0:00:00.279)       0:04:29.082 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Define vm VM0104, hwsku cisco-8101-p4-32x100-vs] ****************
Saturday 16 May 2026  07:33:18 +0000 (0:00:39.217)       0:05:08.300 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0104 if it requires fix] ***************************
Saturday 16 May 2026  07:33:22 +0000 (0:00:04.191)       0:05:12.491 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm VM0104] ************************************************
Saturday 16 May 2026  07:33:22 +0000 (0:00:00.050)       0:05:12.542 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Find out VM index] **********************************************
Saturday 16 May 2026  07:33:27 +0000 (0:00:05.714)       0:05:18.257 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Pause after started every 6 VMs] ********************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.044)       0:05:18.301 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.051)       0:05:18.352 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.034)       0:05:18.387 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.042)       0:05:18.429 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.057)       0:05:18.486 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.069)       0:05:18.556 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.065)       0:05:18.622 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Find current server group] **************************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.068)       0:05:18.690 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Extract VM names from the inventory] ****************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.054)       0:05:18.745 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Generate hostname for target VM] ********************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.057)       0:05:18.803 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.083)       0:05:18.886 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Device debug output] ********************************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.046)       0:05:18.932 ********** 
ok: [STR-ACS-VSERV-01] => {
    "msg": "hostname = VM0105 host internal name = P4 sonic_password = password vm_type = vsonic serial port = 7005 ip = 10.250.0.56 hwsku = cisco-8101-p4-32x100-vs"
}

TASK [vm_set : Check destination file existance] *******************************
Saturday 16 May 2026  07:33:28 +0000 (0:00:00.089)       0:05:19.022 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Copy vsonic disk image for VM0105] ******************************
Saturday 16 May 2026  07:33:29 +0000 (0:00:00.274)       0:05:19.297 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Define vm VM0105, hwsku cisco-8101-p4-32x100-vs] ****************
Saturday 16 May 2026  07:34:27 +0000 (0:00:58.333)       0:06:17.630 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0105 if it requires fix] ***************************
Saturday 16 May 2026  07:34:36 +0000 (0:00:09.099)       0:06:26.730 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm VM0105] ************************************************
Saturday 16 May 2026  07:34:36 +0000 (0:00:00.054)       0:06:26.785 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Find out VM index] **********************************************
Saturday 16 May 2026  07:34:41 +0000 (0:00:05.381)       0:06:32.167 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Pause after started every 6 VMs] ********************************
Saturday 16 May 2026  07:34:41 +0000 (0:00:00.072)       0:06:32.240 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:42 +0000 (0:00:00.073)       0:06:32.313 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart VMs] **************************************************
Saturday 16 May 2026  07:34:42 +0000 (0:00:00.076)       0:06:32.389 ********** 
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/kickstart_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/kickstart_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/kickstart_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/kickstart_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/kickstart_vm.yml for STR-ACS-VSERV-01
included: /data/sonic-mgmt/ansible/roles/vm_set/tasks/kickstart_vm.yml for STR-ACS-VSERV-01

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:42 +0000 (0:00:00.511)       0:06:32.901 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:42 +0000 (0:00:00.039)       0:06:32.940 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:42 +0000 (0:00:00.055)       0:06:32.996 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0100 is loaded] *********************************
Saturday 16 May 2026  07:34:42 +0000 (0:00:00.078)       0:06:33.075 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm] ***********************************************
Saturday 16 May 2026  07:34:42 +0000 (0:00:00.051)       0:06:33.126 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0100] *******************
Saturday 16 May 2026  07:34:42 +0000 (0:00:00.047)       0:06:33.174 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:34:42 +0000 (0:00:00.041)       0:06:33.216 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:43 +0000 (0:00:00.084)       0:06:33.300 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0100 is loaded] *********************************
Saturday 16 May 2026  07:34:43 +0000 (0:00:00.066)       0:06:33.367 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0100 if it hangs] **********************************
Saturday 16 May 2026  07:34:49 +0000 (0:00:06.279)       0:06:39.647 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm again VM0100] ******************************************
Saturday 16 May 2026  07:34:49 +0000 (0:00:00.079)       0:06:39.727 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0100 is loaded] *********************************
Saturday 16 May 2026  07:34:49 +0000 (0:00:00.077)       0:06:39.804 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error again vm VM0100] **************************
Saturday 16 May 2026  07:34:49 +0000 (0:00:00.073)       0:06:39.878 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:34:49 +0000 (0:00:00.082)       0:06:39.960 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0100 is loaded] *********************************
Saturday 16 May 2026  07:34:49 +0000 (0:00:00.086)       0:06:40.047 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin vm VM0100] ***********************************************
Saturday 16 May 2026  07:34:49 +0000 (0:00:00.075)       0:06:40.123 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set cisco vm host] **********************************************
Saturday 16 May 2026  07:34:49 +0000 (0:00:00.055)       0:06:40.178 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Add cisco vm host] **********************************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.181)       0:06:40.359 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check cisco VM0100 reachablity] *********************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.087)       0:06:40.447 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm VM0100] ****************************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.058)       0:06:40.505 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check failed cisco VM0100 reachablity] **************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.065)       0:06:40.571 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0100] *******************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.061)       0:06:40.632 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.150)       0:06:40.782 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.038)       0:06:40.821 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.035)       0:06:40.857 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.037)       0:06:40.894 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0101 is loaded] *********************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.095)       0:06:40.990 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm] ***********************************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.067)       0:06:41.057 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0101] *******************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.053)       0:06:41.111 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.061)       0:06:41.172 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.043)       0:06:41.215 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0101 is loaded] *********************************
Saturday 16 May 2026  07:34:50 +0000 (0:00:00.063)       0:06:41.278 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0101 if it hangs] **********************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:06.040)       0:06:47.319 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm again VM0101] ******************************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.078)       0:06:47.397 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0101 is loaded] *********************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.078)       0:06:47.475 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error again vm VM0101] **************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.056)       0:06:47.531 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.093)       0:06:47.625 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0101 is loaded] *********************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.077)       0:06:47.703 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin vm VM0101] ***********************************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.086)       0:06:47.790 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set cisco vm host] **********************************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.073)       0:06:47.864 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Add cisco vm host] **********************************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.063)       0:06:47.927 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check cisco VM0101 reachablity] *********************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.073)       0:06:48.001 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm VM0101] ****************************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.073)       0:06:48.075 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check failed cisco VM0101 reachablity] **************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.060)       0:06:48.135 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0101] *******************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.056)       0:06:48.192 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:34:57 +0000 (0:00:00.056)       0:06:48.249 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:58 +0000 (0:00:00.055)       0:06:48.304 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:58 +0000 (0:00:00.052)       0:06:48.357 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:58 +0000 (0:00:00.049)       0:06:48.407 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0102 is loaded] *********************************
Saturday 16 May 2026  07:34:58 +0000 (0:00:00.052)       0:06:48.460 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm] ***********************************************
Saturday 16 May 2026  07:34:58 +0000 (0:00:00.046)       0:06:48.506 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0102] *******************
Saturday 16 May 2026  07:34:58 +0000 (0:00:00.049)       0:06:48.556 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:34:58 +0000 (0:00:00.049)       0:06:48.605 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:34:58 +0000 (0:00:00.053)       0:06:48.658 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0102 is loaded] *********************************
Saturday 16 May 2026  07:34:58 +0000 (0:00:00.062)       0:06:48.721 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0102 if it hangs] **********************************
Saturday 16 May 2026  07:35:03 +0000 (0:00:05.162)       0:06:53.884 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm again VM0102] ******************************************
Saturday 16 May 2026  07:35:03 +0000 (0:00:00.082)       0:06:53.966 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0102 is loaded] *********************************
Saturday 16 May 2026  07:35:03 +0000 (0:00:00.071)       0:06:54.038 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error again vm VM0102] **************************
Saturday 16 May 2026  07:35:03 +0000 (0:00:00.061)       0:06:54.099 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:03 +0000 (0:00:00.051)       0:06:54.151 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0102 is loaded] *********************************
Saturday 16 May 2026  07:35:03 +0000 (0:00:00.059)       0:06:54.210 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin vm VM0102] ***********************************************
Saturday 16 May 2026  07:35:03 +0000 (0:00:00.069)       0:06:54.279 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set cisco vm host] **********************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.059)       0:06:54.339 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Add cisco vm host] **********************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.060)       0:06:54.400 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check cisco VM0102 reachablity] *********************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.084)       0:06:54.484 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm VM0102] ****************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.051)       0:06:54.535 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check failed cisco VM0102 reachablity] **************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.058)       0:06:54.594 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0102] *******************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.064)       0:06:54.659 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.067)       0:06:54.727 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.061)       0:06:54.789 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.059)       0:06:54.848 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.065)       0:06:54.914 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0103 is loaded] *********************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.077)       0:06:54.992 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm] ***********************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.064)       0:06:55.057 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0103] *******************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.057)       0:06:55.115 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.059)       0:06:55.174 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:04 +0000 (0:00:00.057)       0:06:55.231 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0103 is loaded] *********************************
Saturday 16 May 2026  07:35:05 +0000 (0:00:00.076)       0:06:55.308 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0103 if it hangs] **********************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:09.192)       0:07:04.501 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm again VM0103] ******************************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.092)       0:07:04.593 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0103 is loaded] *********************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.080)       0:07:04.673 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error again vm VM0103] **************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.070)       0:07:04.744 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.066)       0:07:04.811 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0103 is loaded] *********************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.073)       0:07:04.884 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin vm VM0103] ***********************************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.068)       0:07:04.953 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set cisco vm host] **********************************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.068)       0:07:05.021 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Add cisco vm host] **********************************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.083)       0:07:05.105 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check cisco VM0103 reachablity] *********************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.095)       0:07:05.200 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm VM0103] ****************************************
Saturday 16 May 2026  07:35:14 +0000 (0:00:00.061)       0:07:05.262 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check failed cisco VM0103 reachablity] **************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.071)       0:07:05.334 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0103] *******************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.061)       0:07:05.395 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.059)       0:07:05.454 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.052)       0:07:05.506 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.056)       0:07:05.563 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.055)       0:07:05.619 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0104 is loaded] *********************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.086)       0:07:05.705 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm] ***********************************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.169)       0:07:05.875 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0104] *******************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.076)       0:07:05.952 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.060)       0:07:06.012 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.047)       0:07:06.060 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0104 is loaded] *********************************
Saturday 16 May 2026  07:35:15 +0000 (0:00:00.065)       0:07:06.126 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0104 if it hangs] **********************************
Saturday 16 May 2026  07:35:26 +0000 (0:00:10.434)       0:07:16.561 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm again VM0104] ******************************************
Saturday 16 May 2026  07:35:26 +0000 (0:00:00.079)       0:07:16.640 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0104 is loaded] *********************************
Saturday 16 May 2026  07:35:26 +0000 (0:00:00.073)       0:07:16.713 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error again vm VM0104] **************************
Saturday 16 May 2026  07:35:26 +0000 (0:00:00.092)       0:07:16.806 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:26 +0000 (0:00:00.084)       0:07:16.890 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0104 is loaded] *********************************
Saturday 16 May 2026  07:35:26 +0000 (0:00:00.098)       0:07:16.989 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin vm VM0104] ***********************************************
Saturday 16 May 2026  07:35:26 +0000 (0:00:00.078)       0:07:17.067 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set cisco vm host] **********************************************
Saturday 16 May 2026  07:35:26 +0000 (0:00:00.074)       0:07:17.141 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Add cisco vm host] **********************************************
Saturday 16 May 2026  07:35:26 +0000 (0:00:00.074)       0:07:17.216 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check cisco VM0104 reachablity] *********************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.089)       0:07:17.305 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm VM0104] ****************************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.076)       0:07:17.382 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check failed cisco VM0104 reachablity] **************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.088)       0:07:17.471 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0104] *******************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.074)       0:07:17.546 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.084)       0:07:17.630 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.066)       0:07:17.697 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.069)       0:07:17.767 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.076)       0:07:17.843 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0105 is loaded] *********************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.088)       0:07:17.932 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm] ***********************************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.068)       0:07:18.001 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0105] *******************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.072)       0:07:18.073 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.076)       0:07:18.150 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : set_fact] *******************************************************
Saturday 16 May 2026  07:35:27 +0000 (0:00:00.086)       0:07:18.236 ********** 
ok: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0105 is loaded] *********************************
Saturday 16 May 2026  07:35:28 +0000 (0:00:00.115)       0:07:18.352 ********** 
changed: [STR-ACS-VSERV-01]

TASK [vm_set : Destroy vm VM0105 if it hangs] **********************************
Saturday 16 May 2026  07:35:47 +0000 (0:00:19.338)       0:07:37.690 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start vm again VM0105] ******************************************
Saturday 16 May 2026  07:35:47 +0000 (0:00:00.094)       0:07:37.784 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0105 is loaded] *********************************
Saturday 16 May 2026  07:35:47 +0000 (0:00:00.094)       0:07:37.879 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error again vm VM0105] **************************
Saturday 16 May 2026  07:35:47 +0000 (0:00:00.087)       0:07:37.967 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:47 +0000 (0:00:00.076)       0:07:38.043 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Wait until vm VM0105 is loaded] *********************************
Saturday 16 May 2026  07:35:47 +0000 (0:00:00.079)       0:07:38.123 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin vm VM0105] ***********************************************
Saturday 16 May 2026  07:35:47 +0000 (0:00:00.079)       0:07:38.203 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set cisco vm host] **********************************************
Saturday 16 May 2026  07:35:47 +0000 (0:00:00.064)       0:07:38.268 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Add cisco vm host] **********************************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.068)       0:07:38.337 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check cisco VM0105 reachablity] *********************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.091)       0:07:38.428 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Respin failed vm VM0105] ****************************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.080)       0:07:38.509 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Check failed cisco VM0105 reachablity] **************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.093)       0:07:38.602 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Kickstart gives error after respin vm VM0105] *******************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.070)       0:07:38.673 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Set VM to autostart] ********************************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.078)       0:07:38.752 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Log all kickstart failed VMs] ***********************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.072)       0:07:38.824 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Fail if kickstart any VM failed] ********************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.075)       0:07:38.900 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Connect VMs] ****************************************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.080)       0:07:38.980 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Disconnect VMs] *************************************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.071)       0:07:39.052 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Renumber topology] **********************************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.076)       0:07:39.128 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Add topology] ***************************************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.077)       0:07:39.206 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Remove topology] ************************************************
Saturday 16 May 2026  07:35:48 +0000 (0:00:00.061)       0:07:39.268 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Stop Kubernetes VMs] ********************************************
Saturday 16 May 2026  07:35:49 +0000 (0:00:00.071)       0:07:39.340 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Start Kubernetes VMs] *******************************************
Saturday 16 May 2026  07:35:49 +0000 (0:00:00.076)       0:07:39.417 ********** 
skipping: [STR-ACS-VSERV-01]

TASK [vm_set : Manage the dut state] *******************************************
Saturday 16 May 2026  07:35:49 +0000 (0:00:00.051)       0:07:39.468 ********** 
skipping: [STR-ACS-VSERV-01]

PLAY RECAP *********************************************************************
STR-ACS-VSERV-01           : ok=159  changed=29   unreachable=0    failed=0    skipped=212  rescued=0    ignored=0   

Saturday 16 May 2026  07:35:49 +0000 (0:00:00.053)       0:07:39.522 ********** 
=============================================================================== 
vm_set : Copy vsonic disk image for VM0105 ----------------------------- 58.33s
vm_set : Copy vsonic disk image for VM0102 ----------------------------- 58.20s
vm_set : Copy vsonic disk image for VM0103 ----------------------------- 58.15s
vm_set : Copy vsonic disk image for VM0101 ----------------------------- 43.45s
vm_set : Copy vsonic disk image for VM0100 ----------------------------- 41.00s
vm_set : Copy vsonic disk image for VM0104 ----------------------------- 39.22s
vm_set : Wait until vm VM0105 is loaded -------------------------------- 19.34s
vm_set : Wait until vm VM0104 is loaded -------------------------------- 10.43s
vm_set : Wait until vm VM0103 is loaded --------------------------------- 9.19s
vm_set : Define vm VM0105, hwsku cisco-8101-p4-32x100-vs ---------------- 9.10s
vm_set : Create VMs network --------------------------------------------- 9.00s
vm_set : Get downloaded SONiC image info -------------------------------- 6.37s
vm_set : Wait until vm VM0100 is loaded --------------------------------- 6.28s
vm_set : Check SONiC image ---------------------------------------------- 6.20s
vm_set : Wait until vm VM0101 is loaded --------------------------------- 6.04s
vm_set : Start vm VM0104 ------------------------------------------------ 5.71s
vm_set : Start vm VM0105 ------------------------------------------------ 5.38s
vm_set : Start vm VM0102 ------------------------------------------------ 5.37s
vm_set : Wait until vm VM0102 is loaded --------------------------------- 5.16s
vm_set : Start vm VM0101 ------------------------------------------------ 5.00s
 Id   Name     State
------------------------
 1    VM0100   running
 2    VM0101   running
 3    VM0102   running
 4    VM0103   running
 5    VM0104   running
 6    VM0105   running

CONTAINER ID   IMAGE                             COMMAND                  CREATED          STATUS                     PORTS     NAMES
8e5ae2d928cc   docker-sonic-mgmt-ubuntu:master   "/bin/bash"              8 minutes ago    Up 8 minutes               22/tcp    sonic-mgmt-test
9e992c24ecae   bb450819555d                      "/bin/sh -c 'if ! pi…"   12 minutes ago   Exited (2) 8 minutes ago             sad_mahavira
{'conf-name': 'vms-kvm-t0-3', 'group-name': 'vms6-6', 'topo': 't0', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-06', 'ptf_ip': '10.250.0.116/24', 'ptf_ipv6': 'fec0::ffff:afb:2/64', 'server': 'server_1', 'vm_base': 'VM0132', 'dut': ['vlab-09'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-t0-4', 'group-name': 'vms6-7', 'topo': 't0', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-07', 'ptf_ip': '10.250.0.118/24', 'ptf_ipv6': 'fec0::ffff:afb:4/64', 'server': 'server_1', 'vm_base': 'VM0136', 'dut': ['vlab-10'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-dual-mixed', 'group-name': 'vms6-8', 'topo': 'dualtor-mixed', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-08', 'ptf_ip': '10.250.0.119/24', 'ptf_ipv6': 'fec0::ffff:afa:9/64', 'netns_mgmt_ip': '10.250.0.126/24', 'server': 'server_1', 'vm_base': 'VM0140', 'dut': ['vlab-11', 'vlab-12'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Dual-TOR-Mixed testbed'}
{'conf-name': '8000e-t0', 'group-name': 'vms8-1', 'topo': 't0', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-8k-01', 'ptf_ip': '10.250.0.202/24', 'ptf_ipv6': 'fec0::ffff:afc:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-8k-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests 8000e sonic device'}
{'conf-name': '8000e-t1', 'group-name': 'vms8-1', 'topo': 't1', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-8k-01', 'ptf_ip': '10.250.0.202/24', 'ptf_ipv6': 'fec0::ffff:afc:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-8k-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests 8000e sonic device'}
{'conf-name': 'vms-kvm-wan-pub', 'group-name': 'vms6-1', 'topo': 'wan-pub', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-wan-4link', 'group-name': 'vms6-1', 'topo': 'wan-4link', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-wan-pub-cisco', 'group-name': 'vms6-1', 'topo': 'wan-pub-cisco', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-wan-2dut', 'group-name': 'vms6-1', 'topo': 'wan-2dut', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-01', 'vlab-03'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-wan-3link-tg', 'group-name': 'vms6-1', 'topo': 'wan-3link-tg', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-wan-ecmp', 'group-name': 'vms6-1', 'topo': 'wan-ecmp', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-01', 'vlab-02'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-wan-pub-isis', 'group-name': 'vms6-1', 'topo': 'wan-pub-isis', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual switch vm'}
{'conf-name': 'vms-kvm-dpu', 'group-name': 'vms6-1', 'topo': 'dpu', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-01'], 'inv_name': 'veos_vtb', 'auto_recover': False, 'comment': 'Tests virtual switch vm as DPU'}
{'conf-name': 'vms-kvm-ciscovs-7nodes', 'group-name': 'vms9-1', 'topo': 'ciscovs-7nodes', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-c-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual cisco vs vm with 7 nodes'}
{'conf-name': 'vms-kvm-ciscovs-5nodes', 'group-name': 'vms9-1', 'topo': 'ciscovs-5nodes', 'ptf_image_name': 'docker-ptf', 'ptf': 'ptf-01', 'ptf_ip': '10.250.0.102/24', 'ptf_ipv6': 'fec0::ffff:afa:2/64', 'server': 'server_1', 'vm_base': 'VM0100', 'dut': ['vlab-c-01'], 'inv_name': 'veos_vtb', 'auto_recover': 'False', 'comment': 'Tests virtual cisco vs vm with 5 nodes'}
2026-05-16 00:28:07.204879 : /home/super/workspace/PhoenixWingDailySRv6Test/na_lab/pytest_env/../..//sonic-mgmt/ansible/vars/topo_ciscovs-7nodes.yml : vms_yml {'PE1': {'vlans': [28], 'vm_offset': 0}, 'PE2': {'vlans': [29], 'vm_offset': 1}, 'PE3': {'vlans': [30], 'vm_offset': 2}, 'P3': {'vlans': [31], 'vm_offset': 3}, 'P2': {'vlans': [16], 'vm_offset': 4}, 'P4': {'vlans': [17], 'vm_offset': 5}}, len 6
2026-05-16 00:28:07.205038 : Get input topo vms-kvm-ciscovs-7nodes
2026-05-16 00:28:07.205058 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "docker exec --user ubuntu  sonic-mgmt-test bash -c 'cd /data/sonic-mgmt/ansible;  export PACKAGE_INSTALLATION=false; ./testbed-cli.sh -t vtestbed.yaml -m veos_vtb  -k vsonic  start-topo-vms vms-kvm-ciscovs-7nodes password.txt'"
2026-05-16 00:35:49.424267 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl stop apt-daily.timer"
2026-05-16 00:35:51.176767 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl stop apt-daily-upgrade.timer"
2026-05-16 00:35:52.670960 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl stop apt-daily.service"
2026-05-16 00:35:54.157608 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl stop apt-daily-upgrade.service"
2026-05-16 00:35:55.772001 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl disable apt-daily.timer"
2026-05-16 00:35:57.703836 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl disable apt-daily-upgrade.timer"
2026-05-16 00:35:59.403455 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl disable apt-daily.service"
2026-05-16 00:36:01.230223 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl mask apt-daily.service"
2026-05-16 00:36:03.601058 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl mask apt-daily-upgrade.service"
2026-05-16 00:36:05.190912 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo systemctl mask openvswitch-switch.service"
2026-05-16 00:36:07.039751 : Sleep 10 second
2026-05-16 00:36:17.047130 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo virsh list; docker ps -a"
2026-05-16 00:36:18.380670 : sshpass -p "123" ssh   -q -o "UserKnownHostsFile=/dev/null" -o "StrictHostKeyChecking=no" ubuntu@192.168.0.2 "sudo virsh list | grep VM"
2026-05-16 00:36:19.988631 : DEBUG_ARR:  1    VM0100   running
2026-05-16 00:36:19.988698 : DEBUG_ARR:  2    VM0101   running
2026-05-16 00:36:19.988713 : DEBUG_ARR:  3    VM0102   running
2026-05-16 00:36:19.988726 : DEBUG_ARR:  4    VM0103   running
2026-05-16 00:36:19.988735 : DEBUG_ARR:  5    VM0104   running
2026-05-16 00:36:19.988748 : DEBUG_ARR:  6    VM0105   running
{"Set up Test nodes' VMs in pytest VM": 745.8110816478729}
2026-05-16 00:36:29.999108 : Brought up needed test nodess
2026-05-16 00:36:29.999198 : rm -rf /tmp/local_cache//1778916233.1701105/
--- 756.8338782787323 seconds ---
