2025-10-08 17:11:34,103 - INFO - Domain Default found not creating
2025-10-08 17:11:34,241 - INFO - Project ctest-TestQos-89612728 not found, creating it
2025-10-08 17:11:34,786 - INFO - Created Project:ctest-TestQos-89612728, ID : fe333c83-d6d3-4c35-bf07-b5d9ab4fd738
2025-10-08 17:11:37,046 - DEBUG - Response for create_network : {'network': {'id': 'ac061529-77c8-4caa-8003-489976a6eaca', 'name': 'ctest-vn-05124768', 'tenant_id': 'fe333c83d6d34c35bf07b5d9ab4fd738', 'project_id': 'fe333c83d6d34c35bf07b5d9ab4fd738', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-89612728', 'ctest-vn-05124768'], 'port_security_enabled': True, 'description': ''}}
2025-10-08 17:11:37,344 - DEBUG - Response for create_subnet : {'subnet': {'id': 'd22f39b3-fcfb-43bb-b513-1fbd7c2f4448', 'name': '', 'tenant_id': 'fe333c83d6d34c35bf07b5d9ab4fd738', 'network_id': 'ac061529-77c8-4caa-8003-489976a6eaca', 'ip_version': 4, 'cidr': '171.198.5.192/26', 'allocation_pools': [{'start': '171.198.5.194', 'end': '171.198.5.254'}], 'gateway_ip': '171.198.5.193', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '171.198.5.194', 'tags': [], 'project_id': 'fe333c83d6d34c35bf07b5d9ab4fd738'}}
2025-10-08 17:11:37,656 - DEBUG - Response for create_subnet : {'subnet': {'id': '524522c1-023f-4923-bdbb-fbbbb4c30e7c', 'name': '', 'tenant_id': 'fe333c83d6d34c35bf07b5d9ab4fd738', 'network_id': 'ac061529-77c8-4caa-8003-489976a6eaca', 'ip_version': 6, 'cidr': '36d4:c0c5:f06:dbb4:b97d:29c0::/96', 'allocation_pools': [{'start': '36d4:c0c5:f06:dbb4:b97d:29c0:0:2', 'end': '36d4:c0c5:f06:dbb4:b97d:29c0:ffff:fffe'}], 'gateway_ip': '36d4:c0c5:f06:dbb4:b97d:29c0:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '36d4:c0c5:f06:dbb4:b97d:29c0:0:2', 'tags': [], 'project_id': 'fe333c83d6d34c35bf07b5d9ab4fd738'}}
2025-10-08 17:11:37,695 - INFO - Created VN ctest-vn-05124768
2025-10-08 17:11:37,707 - DEBUG - VN ctest-vn-05124768 UUID is ac061529-77c8-4caa-8003-489976a6eaca
2025-10-08 17:11:38,282 - DEBUG - Response for create_network : {'network': {'id': '6808a9d5-3b8d-491c-b7ea-2171603f69fa', 'name': 'ctest-vn-82030147', 'tenant_id': 'fe333c83d6d34c35bf07b5d9ab4fd738', 'project_id': 'fe333c83d6d34c35bf07b5d9ab4fd738', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-89612728', 'ctest-vn-82030147'], 'port_security_enabled': True, 'description': ''}}
2025-10-08 17:11:38,551 - DEBUG - Response for create_subnet : {'subnet': {'id': 'aaa4dba8-8fb0-4b72-8fe7-ece9e90c24b2', 'name': '', 'tenant_id': 'fe333c83d6d34c35bf07b5d9ab4fd738', 'network_id': '6808a9d5-3b8d-491c-b7ea-2171603f69fa', 'ip_version': 4, 'cidr': '72.84.141.0/26', 'allocation_pools': [{'start': '72.84.141.2', 'end': '72.84.141.62'}], 'gateway_ip': '72.84.141.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '72.84.141.2', 'tags': [], 'project_id': 'fe333c83d6d34c35bf07b5d9ab4fd738'}}
2025-10-08 17:11:38,761 - DEBUG - Response for create_subnet : {'subnet': {'id': 'e4e0aa9a-9b57-4494-a765-4e9bf4b5897a', 'name': '', 'tenant_id': 'fe333c83d6d34c35bf07b5d9ab4fd738', 'network_id': '6808a9d5-3b8d-491c-b7ea-2171603f69fa', 'ip_version': 6, 'cidr': '2534:3d83:9779:cc85:3437:be49::/96', 'allocation_pools': [{'start': '2534:3d83:9779:cc85:3437:be49:0:2', 'end': '2534:3d83:9779:cc85:3437:be49:ffff:fffe'}], 'gateway_ip': '2534:3d83:9779:cc85:3437:be49:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '2534:3d83:9779:cc85:3437:be49:0:2', 'tags': [], 'project_id': 'fe333c83d6d34c35bf07b5d9ab4fd738'}}
2025-10-08 17:11:38,786 - INFO - Created VN ctest-vn-82030147
2025-10-08 17:11:38,799 - DEBUG - VN ctest-vn-82030147 UUID is 6808a9d5-3b8d-491c-b7ea-2171603f69fa
2025-10-08 17:11:38,963 - DEBUG - Services list from nova: [, , , ]
2025-10-08 17:11:39,990 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4239-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4239-1)
2025-10-08 17:11:41,275 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4239-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4239-2)
2025-10-08 17:11:42,850 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4239-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4239-2)
2025-10-08 17:11:42,850 - INFO - Waiting for VM ctest-TestQos-89612728-86274292 to be up..
2025-10-08 17:11:42,957 - DEBUG - VM is in ACTIVE state now
2025-10-08 17:11:42,957 - INFO - VM name : ctest-TestQos-89612728-86274292
2025-10-08 17:11:43,050 - DEBUG - VM ctest-TestQos-89612728-86274292 ID is f52e4fcd-6e2f-42d3-ba5b-acdbed524981
2025-10-08 17:11:43,079 - DEBUG - VM ctest-TestQos-89612728-86274292 launched on Node an-jenkins-deploy-platform-ansible-os-4239-1
2025-10-08 17:11:43,162 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/f52e4fcd-6e2f-42d3-ba5b-acdbed524981
2025-10-08 17:11:43,589 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/f52e4fcd-6e2f-42d3-ba5b-acdbed524981
2025-10-08 17:11:43,634 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/35bffa14-0dcb-4845-bd09-b79f211a8e50
2025-10-08 17:11:46,839 - 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 1005ms')
2025-10-08 17:11:46,839 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-86274292 failed!
2025-10-08 17:11:46,855 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 171.198.5.193 and allocation pool is NOT set
2025-10-08 17:11:46,855 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 36d4:c0c5:f06:dbb4:b97d:29c0:0:1 and allocation pool is NOT set
2025-10-08 17:11:50,930 - 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')
2025-10-08 17:11:50,930 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-86274292 failed!
2025-10-08 17:11:50,944 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 171.198.5.193 and allocation pool is NOT set
2025-10-08 17:11:50,944 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 36d4:c0c5:f06:dbb4:b97d:29c0:0:1 and allocation pool is NOT set
2025-10-08 17:11:55,029 - 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 1026ms')
2025-10-08 17:11:55,029 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-86274292 failed!
2025-10-08 17:11:55,044 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 171.198.5.193 and allocation pool is NOT set
2025-10-08 17:11:55,044 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 36d4:c0c5:f06:dbb4:b97d:29c0:0:1 and allocation pool is NOT set
2025-10-08 17:11:59,126 - 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 1019ms')
2025-10-08 17:11:59,127 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-86274292 failed!
2025-10-08 17:11:59,146 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 171.198.5.193 and allocation pool is NOT set
2025-10-08 17:11:59,147 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 36d4:c0c5:f06:dbb4:b97d:29c0:0:1 and allocation pool is NOT set
2025-10-08 17:12:03,218 - 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')
2025-10-08 17:12:03,218 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-86274292 failed!
2025-10-08 17:12:03,233 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 171.198.5.193 and allocation pool is NOT set
2025-10-08 17:12:03,234 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 36d4:c0c5:f06:dbb4:b97d:29c0:0:1 and allocation pool is NOT set
2025-10-08 17:12:07,321 - 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 1025ms')
2025-10-08 17:12:07,321 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-86274292 failed!
2025-10-08 17:12:07,335 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 171.198.5.193 and allocation pool is NOT set
2025-10-08 17:12:07,335 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 36d4:c0c5:f06:dbb4:b97d:29c0:0:1 and allocation pool is NOT set
2025-10-08 17:12:11,421 - 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 1023ms')
2025-10-08 17:12:11,421 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-86274292 failed!
2025-10-08 17:12:11,435 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 171.198.5.193 and allocation pool is NOT set
2025-10-08 17:12:11,435 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 36d4:c0c5:f06:dbb4:b97d:29c0:0:1 and allocation pool is NOT set
2025-10-08 17:12:15,512 - 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 1013ms')
2025-10-08 17:12:15,512 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-86274292 failed!
2025-10-08 17:12:15,528 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 171.198.5.193 and allocation pool is NOT set
2025-10-08 17:12:15,528 - DEBUG - Gateway for vn default-domain:ctest-TestQos-89612728:ctest-vn-05124768 is 36d4:c0c5:f06:dbb4:b97d:29c0:0:1 and allocation pool is NOT set
2025-10-08 17:12:19,607 - 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=2 ttl=63 time=4.61 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 1 received, 50% packet loss, time 1015ms\r\nrtt min/avg/max/mdev = 4.608/4.608/4.608/0.000 ms')
2025-10-08 17:12:19,607 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-86274292 passed
2025-10-08 17:12:19,676 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:19,676 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-86274292, IP 171.198.5.195, Port 22
2025-10-08 17:12:19,745 - 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': ''}
2025-10-08 17:12:19,815 - DEBUG - VM ctest-TestQos-89612728-86274292 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-08 17:12:24,816 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:24,816 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-86274292, IP 171.198.5.195, Port 22
2025-10-08 17:12:24,885 - 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': ''}
2025-10-08 17:12:24,964 - DEBUG - VM ctest-TestQos-89612728-86274292 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-08 17:12:29,965 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:29,965 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-86274292, IP 171.198.5.195, Port 22
2025-10-08 17:12:30,032 - 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': ''}
2025-10-08 17:12:30,117 - DEBUG - VM ctest-TestQos-89612728-86274292 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-08 17:12:35,118 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:35,118 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-86274292, IP 171.198.5.195, Port 22
2025-10-08 17:12:35,184 - 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': ''}
2025-10-08 17:12:35,264 - DEBUG - VM ctest-TestQos-89612728-86274292 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-08 17:12:40,266 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:40,266 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-86274292, IP 171.198.5.195, Port 22
2025-10-08 17:12:40,426 - DEBUG - VM ctest-TestQos-89612728-86274292 is ready for SSH connections
2025-10-08 17:12:40,426 - INFO - Waiting for VM ctest-TestQos-89612728-42486987 to be up..
2025-10-08 17:12:40,499 - DEBUG - VM is in ACTIVE state now
2025-10-08 17:12:40,499 - INFO - VM name : ctest-TestQos-89612728-42486987
2025-10-08 17:12:40,574 - DEBUG - VM ctest-TestQos-89612728-42486987 ID is 74828de7-f35c-4544-99ef-f443a0438fba
2025-10-08 17:12:40,574 - DEBUG - VM ctest-TestQos-89612728-42486987 launched on Node an-jenkins-deploy-platform-ansible-os-4239-2
2025-10-08 17:12:40,651 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/74828de7-f35c-4544-99ef-f443a0438fba
2025-10-08 17:12:40,663 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/1457e24c-e74c-416a-a009-7585a6bef35a
2025-10-08 17:12:41,827 - 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.22 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=1.29 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1001ms\r\nrtt min/avg/max/mdev = 1.288/4.252/7.217/2.964 ms')
2025-10-08 17:12:41,827 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-89612728-42486987 passed
2025-10-08 17:12:41,905 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:41,905 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-42486987, IP 171.198.5.196, Port 22
2025-10-08 17:12:41,972 - 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': ''}
2025-10-08 17:12:42,073 - DEBUG - VM ctest-TestQos-89612728-42486987 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-08 17:12:47,074 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:47,074 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-42486987, IP 171.198.5.196, Port 22
2025-10-08 17:12:47,139 - 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': ''}
2025-10-08 17:12:47,229 - DEBUG - VM ctest-TestQos-89612728-42486987 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-08 17:12:52,230 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:52,230 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-42486987, IP 171.198.5.196, Port 22
2025-10-08 17:12:52,389 - DEBUG - VM ctest-TestQos-89612728-42486987 is ready for SSH connections
2025-10-08 17:12:52,389 - INFO - Waiting for VM ctest-TestQos-89612728-85771287 to be up..
2025-10-08 17:12:52,493 - DEBUG - VM is in ACTIVE state now
2025-10-08 17:12:52,493 - INFO - VM name : ctest-TestQos-89612728-85771287
2025-10-08 17:12:52,579 - DEBUG - VM ctest-TestQos-89612728-85771287 ID is 1c3a296d-8aee-4701-b5eb-eb951b1d492b
2025-10-08 17:12:52,579 - DEBUG - VM ctest-TestQos-89612728-85771287 launched on Node an-jenkins-deploy-platform-ansible-os-4239-2
2025-10-08 17:12:52,669 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/1c3a296d-8aee-4701-b5eb-eb951b1d492b
2025-10-08 17:12:52,687 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/1b3ebd38-f404-43c3-b81b-aecc8e5ce071
2025-10-08 17:12:53,859 - 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.52 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=0.934 ms\r\n\r\n--- 169.254.0.4 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1002ms\r\nrtt min/avg/max/mdev = 0.934/2.225/3.517/1.291 ms')
2025-10-08 17:12:53,859 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-TestQos-89612728-85771287 passed
2025-10-08 17:12:53,930 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:53,930 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-85771287, IP 72.84.141.3, Port 22
2025-10-08 17:12:54,001 - DEBUG - Error on ssh to ubuntu@169.254.0.4:22, result: /bin/bash: connect: Connection refused
/bin/bash: line 1: /dev/tcp/169.254.0.4/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.4/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.4/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''}
2025-10-08 17:12:54,079 - DEBUG - VM ctest-TestQos-89612728-85771287 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-08 17:12:59,080 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:12:59,080 - DEBUG - Waiting to SSH to VM ctest-TestQos-89612728-85771287, IP 72.84.141.3, Port 22
2025-10-08 17:12:59,252 - DEBUG - VM ctest-TestQos-89612728-85771287 is ready for SSH connections
2025-10-08 17:12:59,256 - INFO - ================================================================================
2025-10-08 17:12:59,256 - INFO - STARTING TEST : test_qos_remark_dscp_on_vmi
2025-10-08 17:12:59,256 - 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
2025-10-08 17:13:00,530 - DEBUG - Nothing to compare xmpp stats {'10.0.0.33': {'10.20.0.192': '0', '10.20.0.19': '0'}, '10.0.0.19': {'10.20.0.192': '0', '10.20.0.19': '0'}} with
2025-10-08 17:13:00,530 - INFO - Initial checks done. Running the testcase now
2025-10-08 17:13:00,530 - INFO -
2025-10-08 17:13:00,535 - DEBUG - FC Dict is {'fc_id': 0, 'dscp': 10, 'dot1p': 1, 'exp': 1, 'connections': }
2025-10-08 17:13:00,804 - INFO - Created FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-13732689'], UUID ac816ffe-72d2-4d6f-a7a9-bae4828a5e46
2025-10-08 17:13:01,200 - INFO - Created QosConfig ['default-domain', 'ctest-TestQos-89612728', 'ctest-qos_config-09023659'], UUID: 10db8c89-dfb2-4574-9b4f-ca5d73a22298
2025-10-08 17:13:01,253 - INFO - Applying qos-config on VM 35bffa14-0dcb-4845-bd09-b79f211a8e50
2025-10-08 17:13:01,511 - DEBUG - VM is in ACTIVE state now
2025-10-08 17:13:01,745 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/f52e4fcd-6e2f-42d3-ba5b-acdbed524981
2025-10-08 17:13:01,755 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/35bffa14-0dcb-4845-bd09-b79f211a8e50
2025-10-08 17:13:01,775 - DEBUG - Requesting: http://10.0.0.41:8082/instance-ip/13661c39-dd95-4af2-a56a-1acf4147bb5a
2025-10-08 17:13:01,786 - DEBUG - Requesting: http://10.0.0.41:8082/instance-ip/804fa383-5c2b-4b47-9754-a0e90db69de6
2025-10-08 17:13:01,996 - DEBUG - VM is in ACTIVE state now
2025-10-08 17:13:02,222 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/74828de7-f35c-4544-99ef-f443a0438fba
2025-10-08 17:13:02,230 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/1457e24c-e74c-416a-a009-7585a6bef35a
2025-10-08 17:13:02,242 - DEBUG - Requesting: http://10.0.0.41:8082/instance-ip/6699602c-2fa5-4ff1-a716-fdd9c68be839
2025-10-08 17:13:02,254 - DEBUG - Requesting: http://10.0.0.41:8082/instance-ip/bc21fb94-e01a-4862-9dff-c60c70a065d3
2025-10-08 17:13:02,284 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:13:02,284 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:13:02,284 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-08 17:13:02,284 - INFO - Starting hping3 on ctest-TestQos-89612728-86274292, args: --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric
2025-10-08 17:13:02,284 - DEBUG - Hping3 cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 171.198.5.196 1>/tmp/hping_ctest-random-32911473.log 2>/tmp/hping_ctest-random-32911473.result
2025-10-08 17:13:02,284 - DEBUG - Running remote_cmd, Cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 171.198.5.196 1>/tmp/hping_ctest-random-32911473.log 2>/tmp/hping_ctest-random-32911473.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.33, gateway password: c0ntrail123
2025-10-08 17:13:02,284 - DEBUG - nohup hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 171.198.5.196 1>/tmp/hping_ctest-random-32911473.log 2>/tmp/hping_ctest-random-32911473.result & echo $! > /tmp/hping_ctest-random-32911473.pid
2025-10-08 17:13:42,595 - DEBUG - None
2025-10-08 17:13:47,759 - DEBUG - Forward flow: {'index': '34616', 'rflow': '74816', 'sip': '171.198.5.195', 'sport': '10000', 'dip': '171.198.5.196', 'dport': '20000', 'proto': '17', 'vrf_id': '2', 'action': 'FORWARD', 'flags': ' ACTIVE | RFLOW_VALID ', 'd_vrf_id': '0', 'bytes': '210', 'pkts': '5', 'insight': '0', 'nhid': '30', 'underlay_udp_sport': '54704', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2025-10-08 17:13:47,760 - DEBUG - Reverse flow: {'index': '74816', 'rflow': '34616', 'sip': '171.198.5.196', 'sport': '20000', 'dip': '171.198.5.195', 'dport': '10000', 'proto': '17', 'vrf_id': '2', 'action': 'FORWARD', 'flags': ' ACTIVE | RFLOW_VALID ', 'd_vrf_id': '0', 'bytes': '350', 'pkts': '5', 'insight': '0', 'nhid': '30', 'underlay_udp_sport': '53347', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2025-10-08 17:13:47,760 - DEBUG - The filter pattern is ['udp', 'and', 'src port 54704']
2025-10-08 17:13:47,760 - DEBUG - The filter string is '(udp and src port 54704)'
2025-10-08 17:13:47,842 - DEBUG - Executing command: sudo tcpdump -nni ens6 -U -vvxx '(udp and src port 54704)' -w /tmp/ens6_ctest-random-45103889.pcap
2025-10-08 17:13:52,935 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2025-10-08 17:13:54,937 - DEBUG - Ensuring hping3 instance with result file /tmp/hping_ctest-random-32911473.result on ctest-TestQos-89612728-86274292 is stopped
2025-10-08 17:13:54,938 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-32911473.pid | xargs kill , host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.33, gateway password: c0ntrail123
2025-10-08 17:13:54,938 - DEBUG - cat /tmp/hping_ctest-random-32911473.pid | xargs kill
2025-10-08 17:13:55,682 - DEBUG - None
2025-10-08 17:13:55,683 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-32911473.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.33, gateway password: c0ntrail123
2025-10-08 17:13:55,683 - DEBUG - cat /tmp/hping_ctest-random-32911473.result
2025-10-08 17:13:56,019 - DEBUG - --- 171.198.5.196 hping statistic ---
13 packets transmitted, 13 packets received, 0% packet loss
round-trip min/avg/max = 12.6/6010.0/12011.8 ms
2025-10-08 17:13:56,019 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-32911473.log, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.33, gateway password: c0ntrail123
2025-10-08 17:13:56,020 - DEBUG - cat /tmp/hping_ctest-random-32911473.log
2025-10-08 17:13:56,330 - DEBUG - HPING 171.198.5.196 (eth0 171.198.5.196): udp mode set, 28 headers + 0 data bytes
ICMP Port Unreachable from ip=171.198.5.196
status=0 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=171.198.5.196
status=1 port=10000 seq=0
2025-10-08 17:13:56,330 - DEBUG - Hping3 stats: {'sent': '13', 'received': '13', 'loss': '0', 'rtt_min': '12.6', 'rtt_avg': '6010.0', 'rtt_max': '12011.8'}
2025-10-08 17:13:56,330 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-45103889.pcap | wc -l
2025-10-08 17:13:56,346 - DEBUG - STDOUT: 16
2025-10-08 17:13:56,346 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-45103889.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2025-10-08 17:13:56,346 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-45103889.pcap but expected 1, which is fine
2025-10-08 17:13:56,346 - INFO - 16 packets are found in tcpdump output as expected
2025-10-08 17:13:56,346 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2025-10-08 17:13:58,403 - DEBUG - ['/contrail-test/ens6_ctest-random-45103889.pcap']
2025-10-08 17:13:58,403 - DEBUG - Verifying for packet number 0
2025-10-08 17:13:58,403 - DEBUG - Validated DSCP marking of 10
2025-10-08 17:13:58,403 - DEBUG - Verifying for packet number 1
2025-10-08 17:13:58,403 - DEBUG - Validated DSCP marking of 10
2025-10-08 17:13:58,403 - DEBUG - Verifying for packet number 2
2025-10-08 17:13:58,403 - DEBUG - Validated DSCP marking of 10
2025-10-08 17:13:58,403 - DEBUG - Verifying for packet number 3
2025-10-08 17:13:58,403 - DEBUG - Validated DSCP marking of 10
2025-10-08 17:13:58,403 - INFO - Packet QoS marking validation passed
2025-10-08 17:13:58,403 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-45103889.pcap | wc -l
2025-10-08 17:13:58,416 - DEBUG - STDOUT: 16
2025-10-08 17:13:58,416 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-45103889.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2025-10-08 17:13:58,416 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-45103889.pcap but expected 1, which is fine
2025-10-08 17:13:58,416 - INFO - 16 packets are found in tcpdump output as expected
2025-10-08 17:13:58,416 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2025-10-08 17:14:00,474 - DEBUG - ['/contrail-test/ens6_ctest-random-45103889.pcap']
2025-10-08 17:14:00,474 - DEBUG - Verifying for packet number 0
2025-10-08 17:14:00,474 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-10-08 17:14:00,474 - DEBUG - Verifying for packet number 1
2025-10-08 17:14:00,474 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-10-08 17:14:00,474 - DEBUG - Verifying for packet number 2
2025-10-08 17:14:00,474 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-10-08 17:14:00,474 - DEBUG - Verifying for packet number 3
2025-10-08 17:14:00,474 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-10-08 17:14:00,474 - INFO - Packet QoS marking validation passed
2025-10-08 17:14:00,585 - INFO - Removing qos-config on VM 35bffa14-0dcb-4845-bd09-b79f211a8e50
2025-10-08 17:14:00,660 - INFO - Deleting Qos config ['default-domain', 'ctest-TestQos-89612728', 'ctest-qos_config-09023659'], UUID: 10db8c89-dfb2-4574-9b4f-ca5d73a22298
2025-10-08 17:14:00,756 - INFO - Deleting FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-13732689'], UUID: ac816ffe-72d2-4d6f-a7a9-bae4828a5e46
2025-10-08 17:14:02,064 - DEBUG - No XMPP flaps were noticed during the test
2025-10-08 17:14:02,065 - INFO - --------------------------------------------------------------------------------
2025-10-08 17:14:02,066 - INFO - Deleting VM ctest-TestQos-89612728-85771287
2025-10-08 17:14:02,135 - INFO - Deleting VM ctest-TestQos-89612728-42486987
2025-10-08 17:14:02,195 - INFO - Deleting VM ctest-TestQos-89612728-86274292
2025-10-08 17:14:02,257 - INFO - Deleting VN ctest-vn-82030147
2025-10-08 17:14:02,298 - DEBUG - VN 6808a9d5-3b8d-491c-b7ea-2171603f69fa still in use: Unable to complete operation on network 6808a9d5-3b8d-491c-b7ea-2171603f69fa. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-d6556bb5-e08a-4fd7-922b-e489ceec2b7b']
2025-10-08 17:14:02,299 - WARNING - Deleting VN ctest-vn-82030147 failed..Will retry
2025-10-08 17:14:04,558 - DEBUG - Response for deleting network ()
2025-10-08 17:14:04,559 - INFO - Deleting VN ctest-vn-05124768
2025-10-08 17:14:04,792 - DEBUG - Response for deleting network ()
2025-10-08 17:14:05,611 - INFO - Deleted project: ctest-TestQos-89612728, ID : fe333c83-d6d3-4c35-bf07-b5d9ab4fd738