2026-02-26 02:54:26,292 - INFO - Domain Default found not creating
2026-02-26 02:54:26,502 - INFO - Project ctest-TestQos-80683271 not found, creating it
2026-02-26 02:54:27,121 - INFO - Created Project:ctest-TestQos-80683271, ID : cc6d63de-8e08-4b12-b01e-c8a41cac6b9f
2026-02-26 02:54:29,993 - DEBUG - Response for create_network : {'network': {'id': '588f6022-34f1-488a-9b2f-6f5ed745403c', 'name': 'ctest-vn-83918325', 'tenant_id': 'cc6d63de8e084b12b01ec8a41cac6b9f', 'project_id': 'cc6d63de8e084b12b01ec8a41cac6b9f', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-80683271', 'ctest-vn-83918325'], 'port_security_enabled': True, 'description': ''}}
2026-02-26 02:54:30,307 - DEBUG - Response for create_subnet : {'subnet': {'id': '1d9c2a03-74d5-4ddf-b08a-7b8a04721cab', 'name': '', 'tenant_id': 'cc6d63de8e084b12b01ec8a41cac6b9f', 'network_id': '588f6022-34f1-488a-9b2f-6f5ed745403c', 'ip_version': 4, 'cidr': '84.104.204.192/26', 'allocation_pools': [{'start': '84.104.204.194', 'end': '84.104.204.254'}], 'gateway_ip': '84.104.204.193', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '84.104.204.194', 'tags': [], 'project_id': 'cc6d63de8e084b12b01ec8a41cac6b9f'}}
2026-02-26 02:54:30,567 - DEBUG - Response for create_subnet : {'subnet': {'id': '1b395b2a-1e72-4d5b-bc3d-2625fa67db5f', 'name': '', 'tenant_id': 'cc6d63de8e084b12b01ec8a41cac6b9f', 'network_id': '588f6022-34f1-488a-9b2f-6f5ed745403c', 'ip_version': 6, 'cidr': '3057:fb36:2261:9691:416f:ca2a::/96', 'allocation_pools': [{'start': '3057:fb36:2261:9691:416f:ca2a:0:2', 'end': '3057:fb36:2261:9691:416f:ca2a:ffff:fffe'}], 'gateway_ip': '3057:fb36:2261:9691:416f:ca2a:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '3057:fb36:2261:9691:416f:ca2a:0:2', 'tags': [], 'project_id': 'cc6d63de8e084b12b01ec8a41cac6b9f'}}
2026-02-26 02:54:30,592 - INFO - Created VN ctest-vn-83918325
2026-02-26 02:54:30,604 - DEBUG - VN ctest-vn-83918325 UUID is 588f6022-34f1-488a-9b2f-6f5ed745403c
2026-02-26 02:54:31,010 - DEBUG - Response for create_network : {'network': {'id': 'df4a2844-eb37-41c7-accf-3da03847ceb5', 'name': 'ctest-vn-16839882', 'tenant_id': 'cc6d63de8e084b12b01ec8a41cac6b9f', 'project_id': 'cc6d63de8e084b12b01ec8a41cac6b9f', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-80683271', 'ctest-vn-16839882'], 'port_security_enabled': True, 'description': ''}}
2026-02-26 02:54:31,226 - DEBUG - Response for create_subnet : {'subnet': {'id': '51816ad0-f40b-4b14-8305-12b9afcc1424', 'name': '', 'tenant_id': 'cc6d63de8e084b12b01ec8a41cac6b9f', 'network_id': 'df4a2844-eb37-41c7-accf-3da03847ceb5', 'ip_version': 4, 'cidr': '3.228.129.192/26', 'allocation_pools': [{'start': '3.228.129.194', 'end': '3.228.129.254'}], 'gateway_ip': '3.228.129.193', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '3.228.129.194', 'tags': [], 'project_id': 'cc6d63de8e084b12b01ec8a41cac6b9f'}}
2026-02-26 02:54:31,465 - DEBUG - Response for create_subnet : {'subnet': {'id': '70cb7683-8560-4376-a778-2e3848dbf020', 'name': '', 'tenant_id': 'cc6d63de8e084b12b01ec8a41cac6b9f', 'network_id': 'df4a2844-eb37-41c7-accf-3da03847ceb5', 'ip_version': 6, 'cidr': '2863:4109:ab03:b653:222b:43ad::/96', 'allocation_pools': [{'start': '2863:4109:ab03:b653:222b:43ad:0:2', 'end': '2863:4109:ab03:b653:222b:43ad:ffff:fffe'}], 'gateway_ip': '2863:4109:ab03:b653:222b:43ad:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '2863:4109:ab03:b653:222b:43ad:0:2', 'tags': [], 'project_id': 'cc6d63de8e084b12b01ec8a41cac6b9f'}}
2026-02-26 02:54:31,490 - INFO - Created VN ctest-vn-16839882
2026-02-26 02:54:31,503 - DEBUG - VN ctest-vn-16839882 UUID is df4a2844-eb37-41c7-accf-3da03847ceb5
2026-02-26 02:54:31,707 - DEBUG - Services list from nova: [, , , ]
2026-02-26 02:54:33,017 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-5402-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-5402-1)
2026-02-26 02:54:34,726 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-5402-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-5402-2)
2026-02-26 02:54:36,913 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-5402-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-5402-2)
2026-02-26 02:54:36,914 - INFO - Waiting for VM ctest-TestQos-80683271-46094406 to be up..
2026-02-26 02:54:37,022 - DEBUG - VM is in ACTIVE state now
2026-02-26 02:54:37,022 - INFO - VM name : ctest-TestQos-80683271-46094406
2026-02-26 02:54:37,142 - DEBUG - VM ctest-TestQos-80683271-46094406 ID is 0905891e-fb95-48bb-8256-290c442a3e38
2026-02-26 02:54:37,174 - DEBUG - VM ctest-TestQos-80683271-46094406 launched on Node an-jenkins-deploy-platform-ansible-os-5402-1
2026-02-26 02:54:37,281 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/0905891e-fb95-48bb-8256-290c442a3e38
2026-02-26 02:54:37,789 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/0905891e-fb95-48bb-8256-290c442a3e38
2026-02-26 02:54:37,861 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/105acbe4-ef6f-4f54-9fdd-156e7b631d50
2026-02-26 02:54:41,075 - 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 1020ms')
2026-02-26 02:54:41,075 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:54:41,090 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:54:41,090 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:54:45,176 - 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-02-26 02:54:45,176 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:54:45,190 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:54:45,191 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:54:49,276 - 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-02-26 02:54:49,276 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:54:49,292 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:54:49,292 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:54:53,369 - 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 1007ms')
2026-02-26 02:54:53,369 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:54:53,388 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:54:53,388 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:54:57,458 - 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 1009ms')
2026-02-26 02:54:57,458 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:54:57,471 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:54:57,472 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:55:01,555 - 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-02-26 02:55:01,555 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:55:01,570 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:55:01,570 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:55:05,658 - 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-02-26 02:55:05,658 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:55:05,675 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:55:05,675 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:55:09,755 - 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-02-26 02:55:09,755 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:55:09,769 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:55:09,769 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:55:13,843 - 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-02-26 02:55:13,843 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:55:13,858 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:55:13,858 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:55:17,937 - 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-02-26 02:55:17,938 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 failed!
2026-02-26 02:55:17,952 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 84.104.204.193 and allocation pool is NOT set
2026-02-26 02:55:17,952 - DEBUG - Gateway for vn default-domain:ctest-TestQos-80683271:ctest-vn-83918325 is 3057:fb36:2261:9691:416f:ca2a:0:1 and allocation pool is NOT set
2026-02-26 02:55:20,018 - 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=7.72 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=3.32 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 = 3.318/5.516/7.715/2.198 ms')
2026-02-26 02:55:20,018 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-46094406 passed
2026-02-26 02:55:20,087 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:20,087 - DEBUG - Waiting to SSH to VM ctest-TestQos-80683271-46094406, IP 84.104.204.195, Port 22
2026-02-26 02:55:20,156 - 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-02-26 02:55:20,273 - DEBUG - VM ctest-TestQos-80683271-46094406 is NOT ready for SSH connections, VM status: ACTIVE
2026-02-26 02:55:25,274 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:25,274 - DEBUG - Waiting to SSH to VM ctest-TestQos-80683271-46094406, IP 84.104.204.195, Port 22
2026-02-26 02:55:25,343 - 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-02-26 02:55:25,436 - DEBUG - VM ctest-TestQos-80683271-46094406 is NOT ready for SSH connections, VM status: ACTIVE
2026-02-26 02:55:30,436 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:30,437 - DEBUG - Waiting to SSH to VM ctest-TestQos-80683271-46094406, IP 84.104.204.195, Port 22
2026-02-26 02:55:30,503 - 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-02-26 02:55:30,600 - DEBUG - VM ctest-TestQos-80683271-46094406 is NOT ready for SSH connections, VM status: ACTIVE
2026-02-26 02:55:35,601 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:35,601 - DEBUG - Waiting to SSH to VM ctest-TestQos-80683271-46094406, IP 84.104.204.195, Port 22
2026-02-26 02:55:35,671 - 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-02-26 02:55:35,772 - DEBUG - VM ctest-TestQos-80683271-46094406 is NOT ready for SSH connections, VM status: ACTIVE
2026-02-26 02:55:40,773 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:40,773 - DEBUG - Waiting to SSH to VM ctest-TestQos-80683271-46094406, IP 84.104.204.195, Port 22
2026-02-26 02:55:40,839 - 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-02-26 02:55:40,944 - DEBUG - VM ctest-TestQos-80683271-46094406 is NOT ready for SSH connections, VM status: ACTIVE
2026-02-26 02:55:45,945 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:45,945 - DEBUG - Waiting to SSH to VM ctest-TestQos-80683271-46094406, IP 84.104.204.195, Port 22
2026-02-26 02:55:46,111 - DEBUG - VM ctest-TestQos-80683271-46094406 is ready for SSH connections
2026-02-26 02:55:46,111 - INFO - Waiting for VM ctest-TestQos-80683271-11483159 to be up..
2026-02-26 02:55:46,253 - DEBUG - VM is in ACTIVE state now
2026-02-26 02:55:46,253 - INFO - VM name : ctest-TestQos-80683271-11483159
2026-02-26 02:55:46,362 - DEBUG - VM ctest-TestQos-80683271-11483159 ID is fc9e43fb-8359-4e3d-8566-c8c712cc8c28
2026-02-26 02:55:46,362 - DEBUG - VM ctest-TestQos-80683271-11483159 launched on Node an-jenkins-deploy-platform-ansible-os-5402-2
2026-02-26 02:55:46,460 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/fc9e43fb-8359-4e3d-8566-c8c712cc8c28
2026-02-26 02:55:46,470 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/4080cbef-4b07-4eb6-a816-e1e06ece66c3
2026-02-26 02:55:47,635 - 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=3.66 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.343 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.343/2.003/3.664/1.660 ms')
2026-02-26 02:55:47,635 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-80683271-11483159 passed
2026-02-26 02:55:47,703 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:47,703 - DEBUG - Waiting to SSH to VM ctest-TestQos-80683271-11483159, IP 84.104.204.196, Port 22
2026-02-26 02:55:47,873 - DEBUG - VM ctest-TestQos-80683271-11483159 is ready for SSH connections
2026-02-26 02:55:47,873 - INFO - Waiting for VM ctest-TestQos-80683271-06054042 to be up..
2026-02-26 02:55:47,965 - DEBUG - VM is in ACTIVE state now
2026-02-26 02:55:47,965 - INFO - VM name : ctest-TestQos-80683271-06054042
2026-02-26 02:55:48,056 - DEBUG - VM ctest-TestQos-80683271-06054042 ID is 93a53b44-a91e-4312-b3d6-e397d379649c
2026-02-26 02:55:48,056 - DEBUG - VM ctest-TestQos-80683271-06054042 launched on Node an-jenkins-deploy-platform-ansible-os-5402-2
2026-02-26 02:55:48,154 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/93a53b44-a91e-4312-b3d6-e397d379649c
2026-02-26 02:55:48,165 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/ee524917-bcab-454a-a0a2-2b1560e4222a
2026-02-26 02:55:49,337 - 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.31 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=1.07 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 = 1.066/2.187/3.308/1.121 ms')
2026-02-26 02:55:49,337 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-TestQos-80683271-06054042 passed
2026-02-26 02:55:49,407 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:49,407 - DEBUG - Waiting to SSH to VM ctest-TestQos-80683271-06054042, IP 3.228.129.195, Port 22
2026-02-26 02:55:49,572 - DEBUG - VM ctest-TestQos-80683271-06054042 is ready for SSH connections
2026-02-26 02:55:49,577 - INFO - ================================================================================
2026-02-26 02:55:49,577 - INFO - STARTING TEST : test_qos_remark_dscp_on_vmi
2026-02-26 02:55:49,577 - 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-02-26 02:55:50,909 - DEBUG - Nothing to compare xmpp stats {'10.0.0.23': {'10.20.0.129': '0', '10.20.0.254': '0'}, '10.0.0.48': {'10.20.0.129': '0', '10.20.0.25': '0'}} with
2026-02-26 02:55:50,909 - INFO - Initial checks done. Running the testcase now
2026-02-26 02:55:50,910 - INFO -
2026-02-26 02:55:50,917 - DEBUG - FC Dict is {'fc_id': 0, 'dscp': 10, 'dot1p': 1, 'exp': 1, 'connections': }
2026-02-26 02:55:51,194 - INFO - Created FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-84501420'], UUID 507913ab-11a1-4a8f-a7b1-4971ed37aa2c
2026-02-26 02:55:51,566 - INFO - Created QosConfig ['default-domain', 'ctest-TestQos-80683271', 'ctest-qos_config-43194039'], UUID: fb800052-9057-4371-b944-d98d7dce6318
2026-02-26 02:55:51,618 - INFO - Applying qos-config on VM 105acbe4-ef6f-4f54-9fdd-156e7b631d50
2026-02-26 02:55:51,874 - DEBUG - VM is in ACTIVE state now
2026-02-26 02:55:52,132 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/0905891e-fb95-48bb-8256-290c442a3e38
2026-02-26 02:55:52,157 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/105acbe4-ef6f-4f54-9fdd-156e7b631d50
2026-02-26 02:55:52,167 - DEBUG - Requesting: http://10.0.0.131:8082/instance-ip/b1c7d525-9521-4b43-9096-523c9fbe8cef
2026-02-26 02:55:52,178 - DEBUG - Requesting: http://10.0.0.131:8082/instance-ip/da2d4194-d16e-4d60-8160-267d2efe7476
2026-02-26 02:55:52,404 - DEBUG - VM is in ACTIVE state now
2026-02-26 02:55:52,676 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine/fc9e43fb-8359-4e3d-8566-c8c712cc8c28
2026-02-26 02:55:52,685 - DEBUG - Requesting: http://10.0.0.131:8082/virtual-machine-interface/4080cbef-4b07-4eb6-a816-e1e06ece66c3
2026-02-26 02:55:52,694 - DEBUG - Requesting: http://10.0.0.131:8082/instance-ip/48b214e1-dcec-44bd-b816-0f25bd3a98a6
2026-02-26 02:55:52,705 - DEBUG - Requesting: http://10.0.0.131:8082/instance-ip/6971cce6-17fd-4daa-bc66-c303bd070728
2026-02-26 02:55:52,741 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:52,741 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:52,741 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2026-02-26 02:55:52,741 - INFO - Starting hping3 on ctest-TestQos-80683271-46094406, args: --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric
2026-02-26 02:55:52,741 - DEBUG - Hping3 cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 84.104.204.196 1>/tmp/hping_ctest-random-41036131.log 2>/tmp/hping_ctest-random-41036131.result
2026-02-26 02:55:52,742 - DEBUG - Running remote_cmd, Cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 84.104.204.196 1>/tmp/hping_ctest-random-41036131.log 2>/tmp/hping_ctest-random-41036131.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123
2026-02-26 02:55:52,742 - DEBUG - nohup hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 84.104.204.196 1>/tmp/hping_ctest-random-41036131.log 2>/tmp/hping_ctest-random-41036131.result & echo $! > /tmp/hping_ctest-random-41036131.pid
2026-02-26 02:56:12,470 - DEBUG - None
2026-02-26 02:56:17,633 - DEBUG - Forward flow: {'index': '422856', 'rflow': '449272', 'sip': '84.104.204.195', 'sport': '10000', 'dip': '84.104.204.196', 'dport': '20000', 'proto': '17', 'vrf_id': '2', 'action': 'FORWARD', 'flags': ' ACTIVE | RFLOW_VALID ', 'd_vrf_id': '0', 'bytes': '252', 'pkts': '6', 'insight': '0', 'nhid': '31', 'underlay_udp_sport': '61958', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2026-02-26 02:56:17,634 - DEBUG - Reverse flow: {'index': '449272', 'rflow': '422856', 'sip': '84.104.204.196', 'sport': '20000', 'dip': '84.104.204.195', 'dport': '10000', 'proto': '17', 'vrf_id': '2', 'action': 'FORWARD', 'flags': ' ACTIVE | RFLOW_VALID ', 'd_vrf_id': '0', 'bytes': '420', 'pkts': '6', 'insight': '0', 'nhid': '31', 'underlay_udp_sport': '56305', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2026-02-26 02:56:17,634 - DEBUG - The filter pattern is ['udp', 'and', 'src port 61958']
2026-02-26 02:56:17,634 - DEBUG - The filter string is '(udp and src port 61958)'
2026-02-26 02:56:17,723 - DEBUG - Executing command: sudo tcpdump -nni ens6 -U -vvxx '(udp and src port 61958)' -w /tmp/ens6_ctest-random-74964506.pcap
2026-02-26 02:56:22,825 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2026-02-26 02:56:24,828 - DEBUG - Ensuring hping3 instance with result file /tmp/hping_ctest-random-41036131.result on ctest-TestQos-80683271-46094406 is stopped
2026-02-26 02:56:24,828 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-41036131.pid | xargs kill , host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123
2026-02-26 02:56:24,828 - DEBUG - cat /tmp/hping_ctest-random-41036131.pid | xargs kill
2026-02-26 02:56:26,532 - DEBUG - None
2026-02-26 02:56:26,532 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-41036131.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123
2026-02-26 02:56:26,532 - DEBUG - cat /tmp/hping_ctest-random-41036131.result
2026-02-26 02:56:27,201 - DEBUG - --- 84.104.204.196 hping statistic ---
14 packets transmitted, 14 packets received, 0% packet loss
round-trip min/avg/max = 17.4/6513.6/13016.6 ms
2026-02-26 02:56:27,202 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-41036131.log, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123
2026-02-26 02:56:27,202 - DEBUG - cat /tmp/hping_ctest-random-41036131.log
2026-02-26 02:56:27,881 - DEBUG - HPING 84.104.204.196 (eth0 84.104.204.196): udp mode set, 28 headers + 0 data bytes
ICMP Port Unreachable from ip=84.104.204.196
status=0 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=84.104.204.196
status=1 port=10000 seq=0
2026-02-26 02:56:27,881 - DEBUG - Hping3 stats: {'sent': '14', 'received': '14', 'loss': '0', 'rtt_min': '17.4', 'rtt_avg': '6513.6', 'rtt_max': '13016.6'}
2026-02-26 02:56:27,881 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-74964506.pcap | wc -l
2026-02-26 02:56:27,899 - DEBUG - STDOUT: 16
2026-02-26 02:56:27,900 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-74964506.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2026-02-26 02:56:27,900 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-74964506.pcap but expected 1, which is fine
2026-02-26 02:56:27,900 - INFO - 16 packets are found in tcpdump output as expected
2026-02-26 02:56:27,900 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2026-02-26 02:56:29,960 - DEBUG - ['/contrail-test/ens6_ctest-random-74964506.pcap']
2026-02-26 02:56:29,960 - DEBUG - Verifying for packet number 0
2026-02-26 02:56:29,960 - DEBUG - Validated DSCP marking of 10
2026-02-26 02:56:29,960 - DEBUG - Verifying for packet number 1
2026-02-26 02:56:29,961 - DEBUG - Validated DSCP marking of 10
2026-02-26 02:56:29,961 - DEBUG - Verifying for packet number 2
2026-02-26 02:56:29,961 - DEBUG - Validated DSCP marking of 10
2026-02-26 02:56:29,961 - DEBUG - Verifying for packet number 3
2026-02-26 02:56:29,961 - DEBUG - Validated DSCP marking of 10
2026-02-26 02:56:29,961 - INFO - Packet QoS marking validation passed
2026-02-26 02:56:29,961 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-74964506.pcap | wc -l
2026-02-26 02:56:29,980 - DEBUG - STDOUT: 16
2026-02-26 02:56:29,980 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-74964506.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2026-02-26 02:56:29,980 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-74964506.pcap but expected 1, which is fine
2026-02-26 02:56:29,980 - INFO - 16 packets are found in tcpdump output as expected
2026-02-26 02:56:29,980 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2026-02-26 02:56:32,035 - DEBUG - ['/contrail-test/ens6_ctest-random-74964506.pcap']
2026-02-26 02:56:32,035 - DEBUG - Verifying for packet number 0
2026-02-26 02:56:32,035 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2026-02-26 02:56:32,035 - DEBUG - Verifying for packet number 1
2026-02-26 02:56:32,035 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2026-02-26 02:56:32,035 - DEBUG - Verifying for packet number 2
2026-02-26 02:56:32,035 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2026-02-26 02:56:32,035 - DEBUG - Verifying for packet number 3
2026-02-26 02:56:32,035 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2026-02-26 02:56:32,035 - INFO - Packet QoS marking validation passed
2026-02-26 02:56:32,153 - INFO - Removing qos-config on VM 105acbe4-ef6f-4f54-9fdd-156e7b631d50
2026-02-26 02:56:32,222 - INFO - Deleting Qos config ['default-domain', 'ctest-TestQos-80683271', 'ctest-qos_config-43194039'], UUID: fb800052-9057-4371-b944-d98d7dce6318
2026-02-26 02:56:32,310 - INFO - Deleting FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-84501420'], UUID: 507913ab-11a1-4a8f-a7b1-4971ed37aa2c
2026-02-26 02:56:33,632 - DEBUG - No XMPP flaps were noticed during the test
2026-02-26 02:56:33,632 - INFO - --------------------------------------------------------------------------------
2026-02-26 02:56:33,634 - INFO - Deleting VM ctest-TestQos-80683271-06054042
2026-02-26 02:56:33,708 - INFO - Deleting VM ctest-TestQos-80683271-11483159
2026-02-26 02:56:33,789 - INFO - Deleting VM ctest-TestQos-80683271-46094406
2026-02-26 02:56:33,869 - INFO - Deleting VN ctest-vn-16839882
2026-02-26 02:56:33,918 - DEBUG - VN df4a2844-eb37-41c7-accf-3da03847ceb5 still in use: Unable to complete operation on network df4a2844-eb37-41c7-accf-3da03847ceb5. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-96ef8e48-9553-46a4-950c-7f4a33e2ba74']
2026-02-26 02:56:33,918 - WARNING - Deleting VN ctest-vn-16839882 failed..Will retry
2026-02-26 02:56:36,144 - DEBUG - Response for deleting network ()
2026-02-26 02:56:36,144 - INFO - Deleting VN ctest-vn-83918325
2026-02-26 02:56:36,411 - DEBUG - Response for deleting network ()
2026-02-26 02:56:37,237 - INFO - Deleted project: ctest-TestQos-80683271, ID : cc6d63de-8e08-4b12-b01e-c8a41cac6b9f