2025-10-29 18:39:53,197 - INFO - Domain Default found not creating
2025-10-29 18:39:53,431 - INFO - Project ctest-TestQos-42068180 not found, creating it
2025-10-29 18:39:54,002 - INFO - Created Project:ctest-TestQos-42068180, ID : 637a35ff-1d63-4b03-b99f-3a2d77d2065b
2025-10-29 18:39:56,602 - DEBUG - Response for create_network : {'network': {'id': '9b66d5bd-85ca-4763-a240-7e56fe5a9215', 'name': 'ctest-vn-26427963', 'tenant_id': '637a35ff1d634b03b99f3a2d77d2065b', 'project_id': '637a35ff1d634b03b99f3a2d77d2065b', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-42068180', 'ctest-vn-26427963'], 'port_security_enabled': True, 'description': ''}}
2025-10-29 18:39:56,936 - DEBUG - Response for create_subnet : {'subnet': {'id': '7c4f7802-22df-416f-b41c-38469d72c207', 'name': '', 'tenant_id': '637a35ff1d634b03b99f3a2d77d2065b', 'network_id': '9b66d5bd-85ca-4763-a240-7e56fe5a9215', 'ip_version': 4, 'cidr': '103.35.15.128/26', 'allocation_pools': [{'start': '103.35.15.130', 'end': '103.35.15.190'}], 'gateway_ip': '103.35.15.129', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '103.35.15.130', 'tags': [], 'project_id': '637a35ff1d634b03b99f3a2d77d2065b'}}
2025-10-29 18:39:57,155 - DEBUG - Response for create_subnet : {'subnet': {'id': '74062c66-3543-485c-b26b-3275d5da6685', 'name': '', 'tenant_id': '637a35ff1d634b03b99f3a2d77d2065b', 'network_id': '9b66d5bd-85ca-4763-a240-7e56fe5a9215', 'ip_version': 6, 'cidr': '3029:1333:1f01:9ad9:47b7:34b::/96', 'allocation_pools': [{'start': '3029:1333:1f01:9ad9:47b7:34b:0:2', 'end': '3029:1333:1f01:9ad9:47b7:34b:ffff:fffe'}], 'gateway_ip': '3029:1333:1f01:9ad9:47b7:34b:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '3029:1333:1f01:9ad9:47b7:34b:0:2', 'tags': [], 'project_id': '637a35ff1d634b03b99f3a2d77d2065b'}}
2025-10-29 18:39:57,180 - INFO - Created VN ctest-vn-26427963
2025-10-29 18:39:57,192 - DEBUG - VN ctest-vn-26427963 UUID is 9b66d5bd-85ca-4763-a240-7e56fe5a9215
2025-10-29 18:39:57,621 - DEBUG - Response for create_network : {'network': {'id': 'd1d754ce-c5c1-4f75-a1c0-e16914dc49b3', 'name': 'ctest-vn-57196979', 'tenant_id': '637a35ff1d634b03b99f3a2d77d2065b', 'project_id': '637a35ff1d634b03b99f3a2d77d2065b', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-42068180', 'ctest-vn-57196979'], 'port_security_enabled': True, 'description': ''}}
2025-10-29 18:39:57,935 - DEBUG - Response for create_subnet : {'subnet': {'id': '0e8dcd5f-8843-4308-90ba-545a89551392', 'name': '', 'tenant_id': '637a35ff1d634b03b99f3a2d77d2065b', 'network_id': 'd1d754ce-c5c1-4f75-a1c0-e16914dc49b3', 'ip_version': 4, 'cidr': '19.4.45.64/26', 'allocation_pools': [{'start': '19.4.45.66', 'end': '19.4.45.126'}], 'gateway_ip': '19.4.45.65', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '19.4.45.66', 'tags': [], 'project_id': '637a35ff1d634b03b99f3a2d77d2065b'}}
2025-10-29 18:39:58,167 - DEBUG - Response for create_subnet : {'subnet': {'id': 'f704df57-b578-4735-be8e-beab340533f8', 'name': '', 'tenant_id': '637a35ff1d634b03b99f3a2d77d2065b', 'network_id': 'd1d754ce-c5c1-4f75-a1c0-e16914dc49b3', 'ip_version': 6, 'cidr': '29ca:1133:54e8:db08:39df:ccb3::/96', 'allocation_pools': [{'start': '29ca:1133:54e8:db08:39df:ccb3:0:2', 'end': '29ca:1133:54e8:db08:39df:ccb3:ffff:fffe'}], 'gateway_ip': '29ca:1133:54e8:db08:39df:ccb3:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '29ca:1133:54e8:db08:39df:ccb3:0:2', 'tags': [], 'project_id': '637a35ff1d634b03b99f3a2d77d2065b'}}
2025-10-29 18:39:58,203 - INFO - Created VN ctest-vn-57196979
2025-10-29 18:39:58,297 - DEBUG - VN ctest-vn-57196979 UUID is d1d754ce-c5c1-4f75-a1c0-e16914dc49b3
2025-10-29 18:39:58,527 - DEBUG - Services list from nova: [, , , ]
2025-10-29 18:39:59,961 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4526-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4526-1)
2025-10-29 18:40:01,536 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4526-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4526-2)
2025-10-29 18:40:03,130 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4526-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4526-2)
2025-10-29 18:40:03,130 - INFO - Waiting for VM ctest-TestQos-42068180-32220577 to be up..
2025-10-29 18:40:03,234 - DEBUG - VM is in ACTIVE state now
2025-10-29 18:40:03,234 - INFO - VM name : ctest-TestQos-42068180-32220577
2025-10-29 18:40:03,345 - DEBUG - VM ctest-TestQos-42068180-32220577 ID is 9dd9c45b-147e-4096-9e05-8da8f17e6e42
2025-10-29 18:40:03,407 - DEBUG - VM ctest-TestQos-42068180-32220577 launched on Node an-jenkins-deploy-platform-ansible-os-4526-1
2025-10-29 18:40:03,517 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/9dd9c45b-147e-4096-9e05-8da8f17e6e42
2025-10-29 18:40:03,977 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/9dd9c45b-147e-4096-9e05-8da8f17e6e42
2025-10-29 18:40:04,022 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/c3196c9a-81cc-4272-bb22-91f5f55413c7
2025-10-29 18:40:07,246 - 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 1010ms')
2025-10-29 18:40:07,246 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 failed!
2025-10-29 18:40:07,273 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 103.35.15.129 and allocation pool is NOT set
2025-10-29 18:40:07,273 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 3029:1333:1f01:9ad9:47b7:34b:0:1 and allocation pool is NOT set
2025-10-29 18:40:11,368 - 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')
2025-10-29 18:40:11,369 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 failed!
2025-10-29 18:40:11,386 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 103.35.15.129 and allocation pool is NOT set
2025-10-29 18:40:11,386 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 3029:1333:1f01:9ad9:47b7:34b:0:1 and allocation pool is NOT set
2025-10-29 18:40:15,497 - 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-29 18:40:15,498 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 failed!
2025-10-29 18:40:15,520 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 103.35.15.129 and allocation pool is NOT set
2025-10-29 18:40:15,520 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 3029:1333:1f01:9ad9:47b7:34b:0:1 and allocation pool is NOT set
2025-10-29 18:40:19,597 - 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')
2025-10-29 18:40:19,597 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 failed!
2025-10-29 18:40:19,620 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 103.35.15.129 and allocation pool is NOT set
2025-10-29 18:40:19,620 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 3029:1333:1f01:9ad9:47b7:34b:0:1 and allocation pool is NOT set
2025-10-29 18:40:23,754 - 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 1036ms')
2025-10-29 18:40:23,754 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 failed!
2025-10-29 18:40:23,775 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 103.35.15.129 and allocation pool is NOT set
2025-10-29 18:40:23,776 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 3029:1333:1f01:9ad9:47b7:34b:0:1 and allocation pool is NOT set
2025-10-29 18:40:27,885 - 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')
2025-10-29 18:40:27,885 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 failed!
2025-10-29 18:40:27,914 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 103.35.15.129 and allocation pool is NOT set
2025-10-29 18:40:27,914 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 3029:1333:1f01:9ad9:47b7:34b:0:1 and allocation pool is NOT set
2025-10-29 18:40:32,010 - 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 1028ms')
2025-10-29 18:40:32,010 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 failed!
2025-10-29 18:40:32,035 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 103.35.15.129 and allocation pool is NOT set
2025-10-29 18:40:32,036 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 3029:1333:1f01:9ad9:47b7:34b:0:1 and allocation pool is NOT set
2025-10-29 18:40:36,141 - 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 1029ms')
2025-10-29 18:40:36,142 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 failed!
2025-10-29 18:40:36,164 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 103.35.15.129 and allocation pool is NOT set
2025-10-29 18:40:36,164 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 3029:1333:1f01:9ad9:47b7:34b:0:1 and allocation pool is NOT set
2025-10-29 18:40:40,268 - 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 1031ms')
2025-10-29 18:40:40,268 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 failed!
2025-10-29 18:40:40,297 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 103.35.15.129 and allocation pool is NOT set
2025-10-29 18:40:40,297 - DEBUG - Gateway for vn default-domain:ctest-TestQos-42068180:ctest-vn-26427963 is 3029:1333:1f01:9ad9:47b7:34b:0:1 and allocation pool is NOT set
2025-10-29 18:40:42,367 - 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=13.0 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.780 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1000ms\r\nrtt min/avg/max/mdev = 0.780/6.886/12.992/6.106 ms')
2025-10-29 18:40:42,367 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-32220577 passed
2025-10-29 18:40:42,449 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:40:42,449 - DEBUG - Waiting to SSH to VM ctest-TestQos-42068180-32220577, IP 103.35.15.131, Port 22
2025-10-29 18:40:42,526 - 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-29 18:40:42,630 - DEBUG - VM ctest-TestQos-42068180-32220577 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-29 18:40:47,631 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:40:47,631 - DEBUG - Waiting to SSH to VM ctest-TestQos-42068180-32220577, IP 103.35.15.131, Port 22
2025-10-29 18:40:47,702 - 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-29 18:40:47,912 - DEBUG - VM ctest-TestQos-42068180-32220577 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-29 18:40:52,913 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:40:52,914 - DEBUG - Waiting to SSH to VM ctest-TestQos-42068180-32220577, IP 103.35.15.131, Port 22
2025-10-29 18:40:53,007 - 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-29 18:40:53,205 - DEBUG - VM ctest-TestQos-42068180-32220577 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-29 18:40:58,206 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:40:58,206 - DEBUG - Waiting to SSH to VM ctest-TestQos-42068180-32220577, IP 103.35.15.131, Port 22
2025-10-29 18:40:58,309 - 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-29 18:40:58,476 - DEBUG - VM ctest-TestQos-42068180-32220577 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-29 18:41:03,477 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:41:03,478 - DEBUG - Waiting to SSH to VM ctest-TestQos-42068180-32220577, IP 103.35.15.131, Port 22
2025-10-29 18:41:03,570 - 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-29 18:41:03,683 - DEBUG - VM ctest-TestQos-42068180-32220577 is NOT ready for SSH connections, VM status: ACTIVE
2025-10-29 18:41:08,684 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:41:08,684 - DEBUG - Waiting to SSH to VM ctest-TestQos-42068180-32220577, IP 103.35.15.131, Port 22
2025-10-29 18:41:08,856 - DEBUG - VM ctest-TestQos-42068180-32220577 is ready for SSH connections
2025-10-29 18:41:08,856 - INFO - Waiting for VM ctest-TestQos-42068180-85880652 to be up..
2025-10-29 18:41:09,012 - DEBUG - VM is in ACTIVE state now
2025-10-29 18:41:09,012 - INFO - VM name : ctest-TestQos-42068180-85880652
2025-10-29 18:41:09,163 - DEBUG - VM ctest-TestQos-42068180-85880652 ID is 38e0528d-62b7-4ce5-8941-a61be4c37a87
2025-10-29 18:41:09,163 - DEBUG - VM ctest-TestQos-42068180-85880652 launched on Node an-jenkins-deploy-platform-ansible-os-4526-2
2025-10-29 18:41:09,278 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/38e0528d-62b7-4ce5-8941-a61be4c37a87
2025-10-29 18:41:09,294 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/e041deb9-df51-4d20-927c-51c2f58243db
2025-10-29 18:41:10,484 - 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=1.78 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=2.37 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 = 1.781/2.077/2.373/0.296 ms')
2025-10-29 18:41:10,485 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-42068180-85880652 passed
2025-10-29 18:41:10,568 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:41:10,569 - DEBUG - Waiting to SSH to VM ctest-TestQos-42068180-85880652, IP 103.35.15.132, Port 22
2025-10-29 18:41:10,734 - DEBUG - VM ctest-TestQos-42068180-85880652 is ready for SSH connections
2025-10-29 18:41:10,734 - INFO - Waiting for VM ctest-TestQos-42068180-86872083 to be up..
2025-10-29 18:41:10,897 - DEBUG - VM is in ACTIVE state now
2025-10-29 18:41:10,898 - INFO - VM name : ctest-TestQos-42068180-86872083
2025-10-29 18:41:11,021 - DEBUG - VM ctest-TestQos-42068180-86872083 ID is df97a307-3f1b-4ca5-a596-95ff0391a469
2025-10-29 18:41:11,022 - DEBUG - VM ctest-TestQos-42068180-86872083 launched on Node an-jenkins-deploy-platform-ansible-os-4526-2
2025-10-29 18:41:11,188 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/df97a307-3f1b-4ca5-a596-95ff0391a469
2025-10-29 18:41:11,202 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/5eb50d91-af5a-46bc-bab1-68224e30112e
2025-10-29 18:41:12,395 - 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.56 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=1.16 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 = 1.156/2.355/3.555/1.199 ms')
2025-10-29 18:41:12,395 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-TestQos-42068180-86872083 passed
2025-10-29 18:41:12,478 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:41:12,478 - DEBUG - Waiting to SSH to VM ctest-TestQos-42068180-86872083, IP 19.4.45.67, Port 22
2025-10-29 18:41:12,645 - DEBUG - VM ctest-TestQos-42068180-86872083 is ready for SSH connections
2025-10-29 18:41:12,655 - INFO - ================================================================================
2025-10-29 18:41:12,656 - INFO - STARTING TEST : test_qos_remark_dscp_on_vmi
2025-10-29 18:41:12,657 - 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-29 18:41:14,069 - DEBUG - Nothing to compare xmpp stats {'10.0.0.73': {'10.20.0.201': '0', '10.20.0.200': '0'}, '10.0.0.27': {'10.20.0.201': '0', '10.20.0.200': '0'}} with
2025-10-29 18:41:14,069 - INFO - Initial checks done. Running the testcase now
2025-10-29 18:41:14,069 - INFO -
2025-10-29 18:41:14,075 - DEBUG - FC Dict is {'fc_id': 0, 'dscp': 10, 'dot1p': 1, 'exp': 1, 'connections': }
2025-10-29 18:41:14,373 - INFO - Created FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-19822061'], UUID 78778b9a-7f8a-4eac-8a8b-16f3b3b8b601
2025-10-29 18:41:14,701 - INFO - Created QosConfig ['default-domain', 'ctest-TestQos-42068180', 'ctest-qos_config-37643434'], UUID: b55c0a23-7344-492e-bf63-5b56c1dbe4d6
2025-10-29 18:41:14,749 - INFO - Applying qos-config on VM c3196c9a-81cc-4272-bb22-91f5f55413c7
2025-10-29 18:41:15,061 - DEBUG - VM is in ACTIVE state now
2025-10-29 18:41:15,486 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/9dd9c45b-147e-4096-9e05-8da8f17e6e42
2025-10-29 18:41:15,497 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/c3196c9a-81cc-4272-bb22-91f5f55413c7
2025-10-29 18:41:15,514 - DEBUG - Requesting: http://10.0.0.41:8082/instance-ip/04838ae7-bed4-4c04-a8c6-8ecc9f8d410d
2025-10-29 18:41:15,529 - DEBUG - Requesting: http://10.0.0.41:8082/instance-ip/b4c88986-992b-49cd-a01f-aac7eaef5319
2025-10-29 18:41:15,848 - DEBUG - VM is in ACTIVE state now
2025-10-29 18:41:16,174 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine/38e0528d-62b7-4ce5-8941-a61be4c37a87
2025-10-29 18:41:16,182 - DEBUG - Requesting: http://10.0.0.41:8082/virtual-machine-interface/e041deb9-df51-4d20-927c-51c2f58243db
2025-10-29 18:41:16,193 - DEBUG - Requesting: http://10.0.0.41:8082/instance-ip/2b864902-cdae-49c7-8a8f-50d9f3d69d1e
2025-10-29 18:41:16,207 - DEBUG - Requesting: http://10.0.0.41:8082/instance-ip/51855a2b-6ffc-42ac-a819-ef67cfe0fac5
2025-10-29 18:41:16,256 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:41:16,256 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:41:16,256 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set
2025-10-29 18:41:16,257 - INFO - Starting hping3 on ctest-TestQos-42068180-32220577, args: --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric
2025-10-29 18:41:16,257 - DEBUG - Hping3 cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 103.35.15.132 1>/tmp/hping_ctest-random-26808459.log 2>/tmp/hping_ctest-random-26808459.result
2025-10-29 18:41:16,257 - DEBUG - Running remote_cmd, Cmd : hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 103.35.15.132 1>/tmp/hping_ctest-random-26808459.log 2>/tmp/hping_ctest-random-26808459.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.73, gateway password: c0ntrail123
2025-10-29 18:41:16,257 - DEBUG - nohup hping3 --destport 20000 --baseport 10000 --count 20000 --interval 1 --udp --tos 4 --keep --numeric 103.35.15.132 1>/tmp/hping_ctest-random-26808459.log 2>/tmp/hping_ctest-random-26808459.result & echo $! > /tmp/hping_ctest-random-26808459.pid
2025-10-29 18:41:33,384 - DEBUG - None
2025-10-29 18:41:38,608 - DEBUG - Forward flow: {'index': '42288', 'rflow': '49396', 'sip': '103.35.15.131', 'sport': '10000', 'dip': '103.35.15.132', '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': '62203', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2025-10-29 18:41:38,609 - DEBUG - Reverse flow: {'index': '49396', 'rflow': '42288', 'sip': '103.35.15.132', 'sport': '20000', 'dip': '103.35.15.131', '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': '52934', 'ttl': '0', 'qos_id': '0', 'gen_id': '1', 'tcp_seq': '0', 'oflow_bytes': '0', 'oflow_packets': '0', 'underlay_gw_index': '-1'}
2025-10-29 18:41:38,609 - DEBUG - The filter pattern is ['udp', 'and', 'src port 62203']
2025-10-29 18:41:38,609 - DEBUG - The filter string is '(udp and src port 62203)'
2025-10-29 18:41:38,711 - DEBUG - Executing command: sudo tcpdump -nni ens6 -U -vvxx '(udp and src port 62203)' -w /tmp/ens6_ctest-random-85652055.pcap
2025-10-29 18:41:44,224 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2025-10-29 18:41:46,230 - DEBUG - Ensuring hping3 instance with result file /tmp/hping_ctest-random-26808459.result on ctest-TestQos-42068180-32220577 is stopped
2025-10-29 18:41:46,231 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-26808459.pid | xargs kill , host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.73, gateway password: c0ntrail123
2025-10-29 18:41:46,231 - DEBUG - cat /tmp/hping_ctest-random-26808459.pid | xargs kill
2025-10-29 18:41:47,140 - DEBUG - None
2025-10-29 18:41:47,140 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-26808459.result, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.73, gateway password: c0ntrail123
2025-10-29 18:41:47,140 - DEBUG - cat /tmp/hping_ctest-random-26808459.result
2025-10-29 18:41:47,523 - DEBUG - --- 103.35.15.132 hping statistic ---
14 packets transmitted, 14 packets received, 0% packet loss
round-trip min/avg/max = 16.3/6515.7/13019.1 ms
2025-10-29 18:41:47,523 - DEBUG - Running remote_cmd, Cmd : cat /tmp/hping_ctest-random-26808459.log, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.73, gateway password: c0ntrail123
2025-10-29 18:41:47,523 - DEBUG - cat /tmp/hping_ctest-random-26808459.log
2025-10-29 18:41:47,979 - DEBUG - HPING 103.35.15.132 (eth0 103.35.15.132): udp mode set, 28 headers + 0 data bytes
ICMP Port Unreachable from ip=103.35.15.132
status=0 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
ICMP Port Unreachable from ip=103.35.15.132
status=1 port=10000 seq=0
2025-10-29 18:41:47,981 - DEBUG - Hping3 stats: {'sent': '14', 'received': '14', 'loss': '0', 'rtt_min': '16.3', 'rtt_avg': '6515.7', 'rtt_max': '13019.1'}
2025-10-29 18:41:47,981 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-85652055.pcap | wc -l
2025-10-29 18:41:48,013 - DEBUG - STDOUT: 16
2025-10-29 18:41:48,013 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-85652055.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2025-10-29 18:41:48,014 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-85652055.pcap but expected 1, which is fine
2025-10-29 18:41:48,014 - INFO - 16 packets are found in tcpdump output as expected
2025-10-29 18:41:48,015 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2025-10-29 18:41:50,092 - DEBUG - ['/contrail-test/ens6_ctest-random-85652055.pcap']
2025-10-29 18:41:50,092 - DEBUG - Verifying for packet number 0
2025-10-29 18:41:50,092 - DEBUG - Validated DSCP marking of 10
2025-10-29 18:41:50,092 - DEBUG - Verifying for packet number 1
2025-10-29 18:41:50,093 - DEBUG - Validated DSCP marking of 10
2025-10-29 18:41:50,093 - DEBUG - Verifying for packet number 2
2025-10-29 18:41:50,093 - DEBUG - Validated DSCP marking of 10
2025-10-29 18:41:50,093 - DEBUG - Verifying for packet number 3
2025-10-29 18:41:50,093 - DEBUG - Validated DSCP marking of 10
2025-10-29 18:41:50,093 - INFO - Packet QoS marking validation passed
2025-10-29 18:41:50,093 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-85652055.pcap | wc -l
2025-10-29 18:41:50,130 - DEBUG - STDOUT: 16
2025-10-29 18:41:50,130 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-85652055.pcap, link-type EN10MB (Ethernet), snapshot length 262144
2025-10-29 18:41:50,131 - DEBUG - 16 packets are found in tcpdump output file /tmp/ens6_ctest-random-85652055.pcap but expected 1, which is fine
2025-10-29 18:41:50,131 - INFO - 16 packets are found in tcpdump output as expected
2025-10-29 18:41:50,131 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}')
2025-10-29 18:41:52,205 - DEBUG - ['/contrail-test/ens6_ctest-random-85652055.pcap']
2025-10-29 18:41:52,205 - DEBUG - Verifying for packet number 0
2025-10-29 18:41:52,206 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-10-29 18:41:52,206 - DEBUG - Verifying for packet number 1
2025-10-29 18:41:52,207 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-10-29 18:41:52,207 - DEBUG - Verifying for packet number 2
2025-10-29 18:41:52,207 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-10-29 18:41:52,207 - DEBUG - Verifying for packet number 3
2025-10-29 18:41:52,207 - DEBUG - Interface ens6 does not seem to be a tagged intf. Skipping dot1p check
2025-10-29 18:41:52,208 - INFO - Packet QoS marking validation passed
2025-10-29 18:41:52,348 - INFO - Removing qos-config on VM c3196c9a-81cc-4272-bb22-91f5f55413c7
2025-10-29 18:41:52,421 - INFO - Deleting Qos config ['default-domain', 'ctest-TestQos-42068180', 'ctest-qos_config-37643434'], UUID: b55c0a23-7344-492e-bf63-5b56c1dbe4d6
2025-10-29 18:41:52,513 - INFO - Deleting FC ['default-global-system-config', 'default-global-qos-config', 'ctest-fc-19822061'], UUID: 78778b9a-7f8a-4eac-8a8b-16f3b3b8b601
2025-10-29 18:41:53,953 - DEBUG - No XMPP flaps were noticed during the test
2025-10-29 18:41:53,954 - INFO - --------------------------------------------------------------------------------
2025-10-29 18:41:53,955 - INFO - Deleting VM ctest-TestQos-42068180-86872083
2025-10-29 18:41:54,127 - INFO - Deleting VM ctest-TestQos-42068180-85880652
2025-10-29 18:41:54,242 - INFO - Deleting VM ctest-TestQos-42068180-32220577
2025-10-29 18:41:54,392 - INFO - Deleting VN ctest-vn-57196979
2025-10-29 18:41:54,466 - DEBUG - VN d1d754ce-c5c1-4f75-a1c0-e16914dc49b3 still in use: Unable to complete operation on network d1d754ce-c5c1-4f75-a1c0-e16914dc49b3. There are one or more ports still in use on the network.
Neutron server returns request_ids: ['req-91da79d6-81f5-478c-bdf8-dc2a4b63eb5a']
2025-10-29 18:41:54,466 - WARNING - Deleting VN ctest-vn-57196979 failed..Will retry
2025-10-29 18:41:56,718 - DEBUG - Response for deleting network ()
2025-10-29 18:41:56,718 - INFO - Deleting VN ctest-vn-26427963
2025-10-29 18:41:56,939 - DEBUG - Response for deleting network ()
2025-10-29 18:41:57,831 - INFO - Deleted project: ctest-TestQos-42068180, ID : 637a35ff-1d63-4b03-b99f-3a2d77d2065b