2026-03-12 02:47:08,649 - INFO - Domain Default found not creating
2026-03-12 02:47:08,813 - INFO - Project ctest-TestQos-91511754 not found, creating it
2026-03-12 02:47:09,408 - INFO - Created Project:ctest-TestQos-91511754, ID : 670d8a4e-398c-454b-96a0-d657a290e195
2026-03-12 02:47:12,261 - DEBUG - Response for create_network : {'network': {'id': 'bde0816c-6685-49a8-b733-624b964afe5b', 'name': 'ctest-vn-00556279', 'tenant_id': '670d8a4e398c454b96a0d657a290e195', 'project_id': '670d8a4e398c454b96a0d657a290e195', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-91511754', 'ctest-vn-00556279'], 'port_security_enabled': True, 'description': ''}}
2026-03-12 02:47:12,547 - DEBUG - Response for create_subnet : {'subnet': {'id': '9002b703-0056-4ca0-ab8b-92ca87227ce7', 'name': '', 'tenant_id': '670d8a4e398c454b96a0d657a290e195', 'network_id': 'bde0816c-6685-49a8-b733-624b964afe5b', 'ip_version': 4, 'cidr': '174.60.217.0/26', 'allocation_pools': [{'start': '174.60.217.2', 'end': '174.60.217.62'}], 'gateway_ip': '174.60.217.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '174.60.217.2', 'tags': [], 'project_id': '670d8a4e398c454b96a0d657a290e195'}}
2026-03-12 02:47:12,760 - DEBUG - Response for create_subnet : {'subnet': {'id': '87e0002b-8723-4fd6-b677-ecefe4691a23', 'name': '', 'tenant_id': '670d8a4e398c454b96a0d657a290e195', 'network_id': 'bde0816c-6685-49a8-b733-624b964afe5b', 'ip_version': 6, 'cidr': '2fa1:f09f:e695:8b55:1fdc:c532::/96', 'allocation_pools': [{'start': '2fa1:f09f:e695:8b55:1fdc:c532:0:2', 'end': '2fa1:f09f:e695:8b55:1fdc:c532:ffff:fffe'}], 'gateway_ip': '2fa1:f09f:e695:8b55:1fdc:c532:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '2fa1:f09f:e695:8b55:1fdc:c532:0:2', 'tags': [], 'project_id': '670d8a4e398c454b96a0d657a290e195'}}
2026-03-12 02:47:12,794 - INFO - Created VN ctest-vn-00556279
2026-03-12 02:47:12,818 - DEBUG - VN ctest-vn-00556279 UUID is bde0816c-6685-49a8-b733-624b964afe5b
2026-03-12 02:47:13,226 - DEBUG - Response for create_network : {'network': {'id': '0c386758-8b52-43df-b92e-4feabf99015a', 'name': 'ctest-vn-55535973', 'tenant_id': '670d8a4e398c454b96a0d657a290e195', 'project_id': '670d8a4e398c454b96a0d657a290e195', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-91511754', 'ctest-vn-55535973'], 'port_security_enabled': True, 'description': ''}}
2026-03-12 02:47:13,430 - DEBUG - Response for create_subnet : {'subnet': {'id': 'b35a771a-d71c-4213-85fd-5df6eb1c333c', 'name': '', 'tenant_id': '670d8a4e398c454b96a0d657a290e195', 'network_id': '0c386758-8b52-43df-b92e-4feabf99015a', 'ip_version': 4, 'cidr': '1.118.104.128/26', 'allocation_pools': [{'start': '1.118.104.130', 'end': '1.118.104.190'}], 'gateway_ip': '1.118.104.129', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '1.118.104.130', 'tags': [], 'project_id': '670d8a4e398c454b96a0d657a290e195'}}
2026-03-12 02:47:13,691 - DEBUG - Response for create_subnet : {'subnet': {'id': '43faf197-1769-409f-bfb2-2a6bdde389b6', 'name': '', 'tenant_id': '670d8a4e398c454b96a0d657a290e195', 'network_id': '0c386758-8b52-43df-b92e-4feabf99015a', 'ip_version': 6, 'cidr': '396c:ad7f:1c2d:caa5:c212:bff4::/96', 'allocation_pools': [{'start': '396c:ad7f:1c2d:caa5:c212:bff4:0:2', 'end': '396c:ad7f:1c2d:caa5:c212:bff4:ffff:fffe'}], 'gateway_ip': '396c:ad7f:1c2d:caa5:c212:bff4:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '396c:ad7f:1c2d:caa5:c212:bff4:0:2', 'tags': [], 'project_id': '670d8a4e398c454b96a0d657a290e195'}}
2026-03-12 02:47:13,719 - INFO - Created VN ctest-vn-55535973
2026-03-12 02:47:13,734 - DEBUG - VN ctest-vn-55535973 UUID is 0c386758-8b52-43df-b92e-4feabf99015a
2026-03-12 02:47:13,899 - DEBUG - Services list from nova: [, , , ]
2026-03-12 02:47:15,005 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-5460-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-5460-1)
2026-03-12 02:47:16,328 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-5460-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-5460-2)
2026-03-12 02:47:17,769 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-5460-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-5460-2)
2026-03-12 02:47:17,769 - INFO - Waiting for VM ctest-TestQos-91511754-05366902 to be up..
2026-03-12 02:47:17,852 - DEBUG - VM is in ACTIVE state now
2026-03-12 02:47:17,852 - INFO - VM name : ctest-TestQos-91511754-05366902
2026-03-12 02:47:17,931 - DEBUG - VM ctest-TestQos-91511754-05366902 ID is abe1c9c3-a4b3-42c6-9f22-47cb7c4859d3
2026-03-12 02:47:17,953 - DEBUG - VM ctest-TestQos-91511754-05366902 launched on Node an-jenkins-deploy-platform-ansible-os-5460-1
2026-03-12 02:47:18,053 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/abe1c9c3-a4b3-42c6-9f22-47cb7c4859d3
2026-03-12 02:47:18,532 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/abe1c9c3-a4b3-42c6-9f22-47cb7c4859d3
2026-03-12 02:47:18,639 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/b03e7833-d4db-4c0d-a2f9-dfa3add70112
2026-03-12 02:47:21,828 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1018ms')
2026-03-12 02:47:21,828 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 failed!
2026-03-12 02:47:21,844 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 174.60.217.1 and allocation pool is NOT set
2026-03-12 02:47:21,844 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 2fa1:f09f:e695:8b55:1fdc:c532:0:1 and allocation pool is NOT set
2026-03-12 02:47:25,925 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1021ms')
2026-03-12 02:47:25,925 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 failed!
2026-03-12 02:47:25,939 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 174.60.217.1 and allocation pool is NOT set
2026-03-12 02:47:25,939 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 2fa1:f09f:e695:8b55:1fdc:c532:0:1 and allocation pool is NOT set
2026-03-12 02:47:30,019 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1022ms')
2026-03-12 02:47:30,019 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 failed!
2026-03-12 02:47:30,034 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 174.60.217.1 and allocation pool is NOT set
2026-03-12 02:47:30,034 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 2fa1:f09f:e695:8b55:1fdc:c532:0:1 and allocation pool is NOT set
2026-03-12 02:47:34,125 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1022ms')
2026-03-12 02:47:34,125 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 failed!
2026-03-12 02:47:34,143 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 174.60.217.1 and allocation pool is NOT set
2026-03-12 02:47:34,143 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 2fa1:f09f:e695:8b55:1fdc:c532:0:1 and allocation pool is NOT set
2026-03-12 02:47:38,216 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1011ms')
2026-03-12 02:47:38,216 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 failed!
2026-03-12 02:47:38,233 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 174.60.217.1 and allocation pool is NOT set
2026-03-12 02:47:38,233 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 2fa1:f09f:e695:8b55:1fdc:c532:0:1 and allocation pool is NOT set
2026-03-12 02:47:42,307 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1014ms')
2026-03-12 02:47:42,308 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 failed!
2026-03-12 02:47:42,327 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 174.60.217.1 and allocation pool is NOT set
2026-03-12 02:47:42,327 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 2fa1:f09f:e695:8b55:1fdc:c532:0:1 and allocation pool is NOT set
2026-03-12 02:47:46,410 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1017ms')
2026-03-12 02:47:46,410 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 failed!
2026-03-12 02:47:46,425 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 174.60.217.1 and allocation pool is NOT set
2026-03-12 02:47:46,425 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 2fa1:f09f:e695:8b55:1fdc:c532:0:1 and allocation pool is NOT set
2026-03-12 02:47:50,500 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1014ms')
2026-03-12 02:47:50,500 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 failed!
2026-03-12 02:47:50,515 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 174.60.217.1 and allocation pool is NOT set
2026-03-12 02:47:50,515 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 2fa1:f09f:e695:8b55:1fdc:c532:0:1 and allocation pool is NOT set
2026-03-12 02:47:54,599 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1018ms')
2026-03-12 02:47:54,599 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 failed!
2026-03-12 02:47:54,615 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 174.60.217.1 and allocation pool is NOT set
2026-03-12 02:47:54,615 - DEBUG - Gateway for vn default-domain:ctest-TestQos-91511754:ctest-vn-00556279 is 2fa1:f09f:e695:8b55:1fdc:c532:0:1 and allocation pool is NOT set
2026-03-12 02:47:56,687 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n64 bytes from 169.254.0.3: icmp_seq=1 ttl=63 time=10.4 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=4.26 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1002ms\r\nrtt min/avg/max/mdev = 4.259/7.309/10.360/3.050 ms')
2026-03-12 02:47:56,687 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-05366902 passed
2026-03-12 02:47:56,761 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:47:56,761 - DEBUG - Waiting to SSH to VM ctest-TestQos-91511754-05366902, IP 174.60.217.3, Port 22
2026-03-12 02:47:56,825 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-03-12 02:47:56,910 - DEBUG - VM ctest-TestQos-91511754-05366902 is NOT ready for SSH connections, VM status: ACTIVE
2026-03-12 02:48:01,910 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:01,911 - DEBUG - Waiting to SSH to VM ctest-TestQos-91511754-05366902, IP 174.60.217.3, Port 22
2026-03-12 02:48:01,968 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-03-12 02:48:02,068 - DEBUG - VM ctest-TestQos-91511754-05366902 is NOT ready for SSH connections, VM status: ACTIVE
2026-03-12 02:48:07,068 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:07,068 - DEBUG - Waiting to SSH to VM ctest-TestQos-91511754-05366902, IP 174.60.217.3, Port 22
2026-03-12 02:48:07,134 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-03-12 02:48:07,228 - DEBUG - VM ctest-TestQos-91511754-05366902 is NOT ready for SSH connections, VM status: ACTIVE
2026-03-12 02:48:12,229 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:12,229 - DEBUG - Waiting to SSH to VM ctest-TestQos-91511754-05366902, IP 174.60.217.3, Port 22
2026-03-12 02:48:12,298 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-03-12 02:48:12,382 - DEBUG - VM ctest-TestQos-91511754-05366902 is NOT ready for SSH connections, VM status: ACTIVE
2026-03-12 02:48:17,382 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:17,382 - DEBUG - Waiting to SSH to VM ctest-TestQos-91511754-05366902, IP 174.60.217.3, Port 22
2026-03-12 02:48:17,549 - DEBUG - VM ctest-TestQos-91511754-05366902 is ready for SSH connections
2026-03-12 02:48:17,550 - INFO - Waiting for VM ctest-TestQos-91511754-12936110 to be up..
2026-03-12 02:48:17,641 - DEBUG - VM is in ACTIVE state now
2026-03-12 02:48:17,641 - INFO - VM name : ctest-TestQos-91511754-12936110
2026-03-12 02:48:17,718 - DEBUG - VM ctest-TestQos-91511754-12936110 ID is b02f571b-5a61-4491-bb26-267b27c798c9
2026-03-12 02:48:17,718 - DEBUG - VM ctest-TestQos-91511754-12936110 launched on Node an-jenkins-deploy-platform-ansible-os-5460-2
2026-03-12 02:48:17,796 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/b02f571b-5a61-4491-bb26-267b27c798c9
2026-03-12 02:48:17,807 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/2985e06f-adf6-4e2e-a21c-96dfc1a35ca4
2026-03-12 02:48:18,970 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n64 bytes from 169.254.0.3: icmp_seq=1 ttl=63 time=2.81 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.948 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1002ms\r\nrtt min/avg/max/mdev = 0.948/1.877/2.806/0.929 ms')
2026-03-12 02:48:18,970 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-91511754-12936110 passed
2026-03-12 02:48:19,043 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:19,043 - DEBUG - Waiting to SSH to VM ctest-TestQos-91511754-12936110, IP 174.60.217.4, Port 22
2026-03-12 02:48:19,113 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-03-12 02:48:19,193 - DEBUG - VM ctest-TestQos-91511754-12936110 is NOT ready for SSH connections, VM status: ACTIVE
2026-03-12 02:48:24,194 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:24,194 - DEBUG - Waiting to SSH to VM ctest-TestQos-91511754-12936110, IP 174.60.217.4, Port 22
2026-03-12 02:48:24,261 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2026-03-12 02:48:24,338 - DEBUG - VM ctest-TestQos-91511754-12936110 is NOT ready for SSH connections, VM status: ACTIVE
2026-03-12 02:48:29,340 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:29,340 - DEBUG - Waiting to SSH to VM ctest-TestQos-91511754-12936110, IP 174.60.217.4, Port 22
2026-03-12 02:48:29,505 - DEBUG - VM ctest-TestQos-91511754-12936110 is ready for SSH connections
2026-03-12 02:48:29,505 - INFO - Waiting for VM ctest-TestQos-91511754-89522743 to be up..
2026-03-12 02:48:29,592 - DEBUG - VM is in ACTIVE state now
2026-03-12 02:48:29,592 - INFO - VM name : ctest-TestQos-91511754-89522743
2026-03-12 02:48:29,673 - DEBUG - VM ctest-TestQos-91511754-89522743 ID is 9404fc2b-0941-48b2-b09b-0dcce84ea095
2026-03-12 02:48:29,673 - DEBUG - VM ctest-TestQos-91511754-89522743 launched on Node an-jenkins-deploy-platform-ansible-os-5460-2
2026-03-12 02:48:29,744 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/9404fc2b-0941-48b2-b09b-0dcce84ea095
2026-03-12 02:48:29,756 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/5e5906a9-5038-4780-84f4-de8a148cf638
2026-03-12 02:48:30,912 - DEBUG - (True, 'PING 169.254.0.4 (169.254.0.4) 56(84) bytes of data.\r\n64 bytes from 169.254.0.4: icmp_seq=1 ttl=63 time=3.11 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=0.405 ms\r\n\r\n--- 169.254.0.4 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1001ms\r\nrtt min/avg/max/mdev = 0.405/1.755/3.106/1.350 ms')
2026-03-12 02:48:30,913 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-TestQos-91511754-89522743 passed
2026-03-12 02:48:30,985 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:30,985 - DEBUG - Waiting to SSH to VM ctest-TestQos-91511754-89522743, IP 1.118.104.131, Port 22
2026-03-12 02:48:31,143 - DEBUG - VM ctest-TestQos-91511754-89522743 is ready for SSH connections
2026-03-12 02:48:31,146 - INFO - ================================================================================
2026-03-12 02:48:31,146 - INFO - STARTING TEST : test_qos_remark_dscp_on_vmi
2026-03-12 02:48:31,146 - INFO - TEST DESCRIPTION : Create a qos config for remarking DSCP 1 to 10
Have VMs A, B
Apply the qos config to VM A
Validate that packets from A to B have DSCP marked correctly
2026-03-12 02:48:32,419 - DEBUG - Nothing to compare xmpp stats {'10.0.0.23': {'10.20.0.17': '0', '10.20.0.129': '0'}, '10.0.0.133': {'10.20.0.17': '0', '10.20.0.129': '0'}} with
2026-03-12 02:48:32,419 - INFO - Initial checks done. Running the testcase now
2026-03-12 02:48:32,419 - INFO -
2026-03-12 02:48:32,425 - DEBUG - FC Dict is {'fc_id': 0, 'dscp': 10, 'dot1p': 1, 'exp': 1, 'connections': }
2026-03-12 02:48:32,700 - INFO - Created FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-57941590'], UUID 4c6f5795-d148-45e4-a103-65e988d8be6a
2026-03-12 02:48:33,020 - INFO - Created QosConfig ['default-domain', 'ctest-TestQos-91511754', 'ctest-qos_config-89519915'], UUID: 6947c6b2-faa5-435d-be07-470962d37e8e
2026-03-12 02:48:33,072 - INFO - Applying qos-config on VM b03e7833-d4db-4c0d-a2f9-dfa3add70112
2026-03-12 02:48:33,315 - DEBUG - VM is in ACTIVE state now
2026-03-12 02:48:33,536 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/abe1c9c3-a4b3-42c6-9f22-47cb7c4859d3
2026-03-12 02:48:33,545 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/b03e7833-d4db-4c0d-a2f9-dfa3add70112
2026-03-12 02:48:33,555 - DEBUG - Requesting: http://10.0.0.131:8082/instance-ip/63b7304b-5dcf-412b-ae50-458a1c3b7074
2026-03-12 02:48:33,565 - DEBUG - Requesting: http://10.0.0.131:8082/instance-ip/ef4ebc21-4422-4521-905d-89cbca24c464
2026-03-12 02:48:33,748 - DEBUG - VM is in ACTIVE state now
2026-03-12 02:48:33,966 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/b02f571b-5a61-4491-bb26-267b27c798c9
2026-03-12 02:48:33,973 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/2985e06f-adf6-4e2e-a21c-96dfc1a35ca4
2026-03-12 02:48:33,983 - DEBUG - Requesting: http://10.0.0.131:8082/instance-ip/240e4a21-6b66-4654-8119-19cb9ec53954
2026-03-12 02:48:33,993 - DEBUG - Requesting: http://10.0.0.131:8082/instance-ip/5ff651f4-3b71-4cdb-8b0f-fe12c8e9c607
2026-03-12 02:48:34,022 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:34,022 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:34,023 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-03-12 02:48:34,023 - INFO - Starting hping3 on ctest-TestQos-91511754-05366902, args: --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric
2026-03-12 02:48:34,023 - DEBUG - Hping3 cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 174.60.217.4 1>/tmp/hping_ctest-random-00136206.log 2>/tmp/hping_ctest-random-00136206.result
2026-03-12 02:48:34,023 - DEBUG - Running remote_cmd, Cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 174.60.217.4 1>/tmp/hping_ctest-random-00136206.log 2>/tmp/hping_ctest-random-00136206.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123
2026-03-12 02:48:34,023 - DEBUG - nohup hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 174.60.217.4 1>/tmp/hping_ctest-random-00136206.log 2>/tmp/hping_ctest-random-00136206.result & echo $! > /tmp/hping_ctest-random-00136206.pid
2026-03-12 02:48:42,197 - DEBUG - None
2026-03-12 02:48:47,374 - DEBUG - Forward flow: {'index': '16108', 'rflow': '254400', 'sip': '174.60.217.3', 'sport': '10000', 'dip': '174.60.217.4', 'dport': '20000', 'proto': '17', 'vrf_id': '2', 'action': 'FORWARD', 'flags': ' ACTIVE | RFLOW_VALID ', 'd_vrf_id': '0', 'bytes': '210', 'pkts': '5', 'insight': '0', 'nhid': '31', 'underlay_udp_sport': '58682', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2026-03-12 02:48:47,375 - DEBUG - Reverse flow: {'index': '254400', 'rflow': '16108', 'sip': '174.60.217.4', 'sport': '20000', 'dip': '174.60.217.3', 'dport': '10000', 'proto': '17', 'vrf_id': '2', 'action': 'FORWARD', 'flags': ' ACTIVE | RFLOW_VALID ', 'd_vrf_id': '0', 'bytes': '350', 'pkts': '5', 'insight': '0', 'nhid': '31', 'underlay_udp_sport': '49996', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2026-03-12 02:48:47,375 - DEBUG - The filter pattern is ['udp', 'and', 'src port 58682']
2026-03-12 02:48:47,375 - DEBUG - The filter string is '(udp and src port 58682)'
2026-03-12 02:48:47,459 - DEBUG - Executing command: sudo tcpdump -nni ens6 -U -vvxx '(udp and src port 58682)' -w /tmp/ens6_ctest-random-79926293.pcap
2026-03-12 02:48:52,582 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2026-03-12 02:48:54,585 - DEBUG - Ensuring hping3 instance with result file /tmp/hping_ctest-random-00136206.result on ctest-TestQos-91511754-05366902 is stopped
2026-03-12 02:48:54,586 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-00136206.pid | xargs kill , host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123
2026-03-12 02:48:54,586 - DEBUG - cat /tmp/hping_ctest-random-00136206.pid | xargs kill
2026-03-12 02:48:55,445 - DEBUG - None
2026-03-12 02:48:55,445 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-00136206.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123
2026-03-12 02:48:55,445 - DEBUG - cat /tmp/hping_ctest-random-00136206.result
2026-03-12 02:48:55,804 - DEBUG - --- 174.60.217.4 hping statistic ---
14 packets transmitted, 14 packets received, 0% packet loss
round-trip min/avg/max = 18.6/6511.7/13014.2 ms
2026-03-12 02:48:55,804 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-00136206.log, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123
2026-03-12 02:48:55,804 - DEBUG - cat /tmp/hping_ctest-random-00136206.log
2026-03-12 02:48:56,155 - DEBUG - HPING 174.60.217.4 (eth0 174.60.217.4): udp mode set, 28 headers + 0 data bytes
ICMP Port Unreachable from ip=174.60.217.4
status=0 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=174.60.217.4
status=1 port=10000 seq=0
2026-03-12 02:48:56,156 - DEBUG - Hping3 stats: {'sent': '14', 'received': '14', 'loss': '0', 'rtt_min': '18.6', 'rtt_avg': '6511.7', 'rtt_max': '13014.2'}
2026-03-12 02:48:56,156 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-79926293.pcap | wc -l
2026-03-12 02:48:56,172 - DEBUG - STDOUT: 16
2026-03-12 02:48:56,172 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-79926293.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2026-03-12 02:48:56,173 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-79926293.pcap but expected 1, which is fine
2026-03-12 02:48:56,173 - INFO - 16 packets are found in tcpdump output as expected
2026-03-12 02:48:56,173 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2026-03-12 02:48:58,234 - DEBUG - ['/contrail-test/ens6_ctest-random-79926293.pcap']
2026-03-12 02:48:58,235 - DEBUG - Verifying for packet number 0
2026-03-12 02:48:58,235 - DEBUG - Validated DSCP marking of 10
2026-03-12 02:48:58,235 - DEBUG - Verifying for packet number 1
2026-03-12 02:48:58,235 - DEBUG - Validated DSCP marking of 10
2026-03-12 02:48:58,235 - DEBUG - Verifying for packet number 2
2026-03-12 02:48:58,235 - DEBUG - Validated DSCP marking of 10
2026-03-12 02:48:58,235 - DEBUG - Verifying for packet number 3
2026-03-12 02:48:58,235 - DEBUG - Validated DSCP marking of 10
2026-03-12 02:48:58,235 - INFO - Packet QoS marking validation passed
2026-03-12 02:48:58,238 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-79926293.pcap | wc -l
2026-03-12 02:48:58,255 - DEBUG - STDOUT: 16
2026-03-12 02:48:58,255 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-79926293.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2026-03-12 02:48:58,255 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-79926293.pcap but expected 1, which is fine
2026-03-12 02:48:58,255 - INFO - 16 packets are found in tcpdump output as expected
2026-03-12 02:48:58,255 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2026-03-12 02:49:00,315 - DEBUG - ['/contrail-test/ens6_ctest-random-79926293.pcap']
2026-03-12 02:49:00,315 - DEBUG - Verifying for packet number 0
2026-03-12 02:49:00,315 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2026-03-12 02:49:00,315 - DEBUG - Verifying for packet number 1
2026-03-12 02:49:00,315 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2026-03-12 02:49:00,315 - DEBUG - Verifying for packet number 2
2026-03-12 02:49:00,315 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2026-03-12 02:49:00,315 - DEBUG - Verifying for packet number 3
2026-03-12 02:49:00,315 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2026-03-12 02:49:00,315 - INFO - Packet QoS marking validation passed
2026-03-12 02:49:00,433 - INFO - Removing qos-config on VM b03e7833-d4db-4c0d-a2f9-dfa3add70112
2026-03-12 02:49:00,512 - INFO - Deleting Qos config ['default-domain', 'ctest-TestQos-91511754', 'ctest-qos_config-89519915'], UUID: 6947c6b2-faa5-435d-be07-470962d37e8e
2026-03-12 02:49:00,600 - INFO - Deleting FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-57941590'], UUID: 4c6f5795-d148-45e4-a103-65e988d8be6a
2026-03-12 02:49:01,909 - DEBUG - No XMPP flaps were noticed during the test
2026-03-12 02:49:01,909 - INFO - --------------------------------------------------------------------------------
2026-03-12 02:49:01,911 - INFO - Deleting VM ctest-TestQos-91511754-89522743
2026-03-12 02:49:01,978 - INFO - Deleting VM ctest-TestQos-91511754-12936110
2026-03-12 02:49:02,046 - INFO - Deleting VM ctest-TestQos-91511754-05366902
2026-03-12 02:49:02,114 - INFO - Deleting VN ctest-vn-55535973
2026-03-12 02:49:02,163 - DEBUG - VN 0c386758-8b52-43df-b92e-4feabf99015a still in use: Unable to complete operation on network 0c386758-8b52-43df-b92e-4feabf99015a. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-67b7e491-437c-4e90-931a-6b0aa1434b87']
2026-03-12 02:49:02,163 - WARNING - Deleting VN ctest-vn-55535973 failed..Will retry
2026-03-12 02:49:04,342 - DEBUG - Response for deleting network ()
2026-03-12 02:49:04,342 - INFO - Deleting VN ctest-vn-00556279
2026-03-12 02:49:04,518 - DEBUG - Response for deleting network ()
2026-03-12 02:49:05,248 - INFO - Deleted project: ctest-TestQos-91511754, ID : 670d8a4e-398c-454b-96a0-d657a290e195